From d5f5fc1b8f7336c8f58223c86e94a309ac139d0b Mon Sep 17 00:00:00 2001 From: Ashley Venn Date: Thu, 2 Jul 2026 18:46:58 -0700 Subject: [PATCH] feat: add flexible task action logging --- .../flexible_task_action_service.dart | 432 +++++++++++++++++- 1 file changed, 423 insertions(+), 9 deletions(-) diff --git a/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart b/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart index 12870b9..c0715bb 100644 --- a/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart +++ b/packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart @@ -3,6 +3,145 @@ part of '../../task_actions.dart'; +/// Lazily creates a flexible-task action log message after level gating passes. +typedef FlexibleTaskActionLogMessage = Object? Function(); + +/// Receives a flexible-task action log entry. +typedef FlexibleTaskActionLogSink = void Function( + FlexibleTaskActionLogEntry entry, +); + +/// Log levels used by [FlexibleTaskActionService]. +enum FlexibleTaskActionLogLevel { + /// Extremely granular data dumps with automatic caller information. + finest, + + /// Intra-method minor actions and small state changes. + finer, + + /// Secondary details, possible issues, and rich warning/error context. + fine, + + /// High-level debug flow and state values. + debug, + + /// Very high-level healthy lifecycle checkpoints. + info, + + /// Handled issues where the service recovered and returned a safe result. + warn, + + /// Invalid or unsafe states that should be reviewed. + error, +} + +/// Structured log entry emitted by [FlexibleTaskActionLogger]. +class FlexibleTaskActionLogEntry { + /// Creates a log entry for one flexible-task action event. + const FlexibleTaskActionLogEntry({ + required this.level, + required this.message, + this.caller, + }); + + /// Severity level for this entry. + final FlexibleTaskActionLogLevel level; + + /// Already-resolved message text. + final String message; + + /// Optional source frame captured according to the configured level. + final String? caller; +} + +/// Optional logger used by [FlexibleTaskActionService]. +/// +/// The default constructor is disabled, so existing callers pay only a cheap +/// null/level check. Expensive message construction should be guarded with +/// [isEnabled] and passed as a [FlexibleTaskActionLogMessage]. +class FlexibleTaskActionLogger { + /// Creates a logger that drops every message. + const FlexibleTaskActionLogger.disabled() + : minimumLevel = null, + sink = null; + + /// Creates a logger that sends enabled entries to [sink]. + const FlexibleTaskActionLogger({ + required this.minimumLevel, + required this.sink, + }); + + /// Minimum level to emit, or null when disabled. + final FlexibleTaskActionLogLevel? minimumLevel; + + /// Destination for enabled log entries. + final FlexibleTaskActionLogSink? sink; + + /// Whether [level] would be emitted by this logger. + bool isEnabled(FlexibleTaskActionLogLevel level) { + final configured = minimumLevel; + return configured != null && + sink != null && + _shouldWrite(level, configured); + } + + /// Logs [message] at `finest` when enabled. + void finest(Object? message) { + write(FlexibleTaskActionLogLevel.finest, message); + } + + /// Logs [message] at `finer` when enabled. + void finer(Object? message) { + write(FlexibleTaskActionLogLevel.finer, message); + } + + /// Logs [message] at `fine` when enabled. + void fine(Object? message) { + write(FlexibleTaskActionLogLevel.fine, message); + } + + /// Logs [message] at `debug` when enabled. + void debug(Object? message) { + write(FlexibleTaskActionLogLevel.debug, message); + } + + /// Logs [message] at `info` when enabled. + void info(Object? message) { + write(FlexibleTaskActionLogLevel.info, message); + } + + /// Logs [message] at `warn` when enabled. + void warn(Object? message) { + write(FlexibleTaskActionLogLevel.warn, message); + } + + /// Logs [message] at `error` when enabled. + void error(Object? message) { + write(FlexibleTaskActionLogLevel.error, message); + } + + /// Logs [message] at [level] when enabled. + void write(FlexibleTaskActionLogLevel level, Object? message) { + final configured = minimumLevel; + final currentSink = sink; + if (configured == null || + currentSink == null || + !_shouldWrite(level, configured)) { + return; + } + + currentSink( + FlexibleTaskActionLogEntry( + level: level, + message: _resolveLogMessage(message), + caller: _shouldCaptureCaller(level: level, minimumLevel: configured) + ? _callerFrame() + : null, + ), + ); + } +} + /// Applies low-friction quick actions for flexible task cards. /// /// This service is the adapter between small UI button presses and domain logic. @@ -16,6 +155,7 @@ class FlexibleTaskActionService { this.schedulingEngine = const SchedulingEngine(), this.transitionService = const TaskTransitionService(), this.clock = const SystemClock(), + this.logger = const FlexibleTaskActionLogger.disabled(), }); /// Scheduling dependency used for actions that need timeline changes. @@ -27,6 +167,9 @@ class FlexibleTaskActionService { /// Clock boundary used when an action timestamp is not supplied. final Clock clock; + /// Optional logger for diagnostics around flexible task actions. + final FlexibleTaskActionLogger logger; + /// Apply the first-stage quick action. /// /// Direct actions (`done`, `backlog`) return a changed task. `push` returns the @@ -43,15 +186,42 @@ class FlexibleTaskActionService { Iterable existingActivities = const [], }) { if (!task.isFlexible) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.error)) { + logger.error(() => 'Flexible action rejected for non-flexible task. ' + 'action=${action.name} taskId=${task.id} taskType=${task.type.name} ' + 'taskStatus=${task.status.name}'); + } throw ArgumentError.value( task.type, 'task.type', 'Task must be flexible.'); } + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Applying flexible quick action. ' + 'action=${action.name} taskId=${task.id} ' + 'taskStatus=${task.status.name} hasExplicitUpdatedAt=${updatedAt != null} ' + 'hasOperationId=${operationId != null}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Flexible quick action input dump. ' + 'action=${action.name} task=${_taskSummary(task)} ' + 'updatedAt=${updatedAt?.toIso8601String()} operationId=$operationId ' + 'actualStart=${actualStart?.toIso8601String()} ' + 'actualEnd=${actualEnd?.toIso8601String()} ' + 'lockedIntervals=${_intervalSummary(lockedIntervals)} ' + 'existingActivityCount=${existingActivities.length}'); + } + switch (action) { case FlexibleTaskQuickAction.done: final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId(action.name, task.id, now); + if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { + logger.finer(() => 'Completing flexible task. taskId=${task.id} ' + 'operationId=$opId occurredAt=${now.toIso8601String()} ' + 'hasActualStart=${actualStart != null} hasActualEnd=${actualEnd != null} ' + 'lockedIntervalCount=${lockedIntervals.length}'); + } final transition = transitionService.apply( task: task, transitionCode: TaskTransitionCode.complete, @@ -67,6 +237,19 @@ class FlexibleTaskActionService { lockedIntervals: lockedIntervals, existingActivities: existingActivities, ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible task completion transition finished. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'nextStatus=${transition.task.status.name} ' + 'activityCount=${transition.activities.length}'); + } + if (transition.outcomeCode != TaskTransitionOutcomeCode.applied && + logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { + logger.fine(() => + 'Possible issue: flexible completion did not apply. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'previousStatus=${task.status.name} nextStatus=${transition.task.status.name}'); + } return FlexibleTaskActionResult( action: action, task: transition.task, @@ -74,6 +257,15 @@ class FlexibleTaskActionService { transitionOutcomeCode: transition.outcomeCode, ); case FlexibleTaskQuickAction.push: + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible push destination menu requested. ' + 'taskId=${task.id} taskStatus=${task.status.name}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { + logger.finer(() => 'Flexible push destinations prepared. ' + 'taskId=${task.id} destinations=' + '${PushDestination.values.map((destination) => destination.name).join(',')}'); + } return FlexibleTaskActionResult( action: action, task: task, @@ -87,6 +279,13 @@ class FlexibleTaskActionService { final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId(action.name, task.id, now); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger + .debug(() => 'Moving flexible task to backlog from quick action. ' + 'taskId=${task.id} operationId=$opId ' + 'occurredAt=${now.toIso8601String()} ' + 'previousStatus=${task.status.name}'); + } final transition = transitionService.apply( task: task, transitionCode: TaskTransitionCode.moveToBacklog, @@ -99,6 +298,19 @@ class FlexibleTaskActionService { occurredAt: now, existingActivities: existingActivities, ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible task backlog transition finished. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'nextStatus=${transition.task.status.name} ' + 'activityCount=${transition.activities.length}'); + } + if (transition.outcomeCode != TaskTransitionOutcomeCode.applied && + logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { + logger.fine(() => + 'Possible issue: move-to-backlog quick action did not apply. ' + 'taskId=${task.id} outcome=${transition.outcomeCode.name} ' + 'previousStatus=${task.status.name} nextStatus=${transition.task.status.name}'); + } return FlexibleTaskActionResult( action: action, task: transition.task, @@ -106,6 +318,10 @@ class FlexibleTaskActionService { transitionOutcomeCode: transition.outcomeCode, ); case FlexibleTaskQuickAction.breakUp: + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible break-up flow requested. ' + 'taskId=${task.id} taskStatus=${task.status.name}'); + } return FlexibleTaskActionResult( action: action, task: task, @@ -129,11 +345,30 @@ class FlexibleTaskActionService { final now = updatedAt ?? clock.now(); final opId = operationId ?? _defaultOperationId('push-${destination.name}', taskId, now); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Applying flexible push destination. ' + 'destination=${destination.name} taskId=$taskId operationId=$opId ' + 'occurredAt=${now.toIso8601String()} taskCount=${input.tasks.length} ' + 'windowStart=${input.window.start.toIso8601String()} ' + 'windowEnd=${input.window.end.toIso8601String()}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Flexible push destination input dump. ' + 'destination=${destination.name} taskId=$taskId ' + 'tasks=${_taskListSummary(input.tasks)} ' + 'lockedIntervals=${_intervalSummary(input.lockedIntervals)} ' + 'requiredVisibleIntervals=${_intervalSummary(input.requiredVisibleIntervals)} ' + 'existingActivityCount=${existingActivities.length}'); + } if (_hasDuplicateActivity( existingActivities: existingActivities, operationId: opId, taskId: taskId, )) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Duplicate flexible push operation ignored. ' + 'destination=${destination.name} taskId=$taskId operationId=$opId'); + } return PushDestinationResult( destination: destination, schedulingResult: SchedulingResult( @@ -147,6 +382,10 @@ class FlexibleTaskActionService { ); } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finer)) { + logger.finer(() => 'Dispatching flexible push destination to scheduler. ' + 'destination=${destination.name} taskId=$taskId'); + } final result = switch (destination) { PushDestination.nextAvailableSlot => schedulingEngine.pushFlexibleTaskToNextAvailableSlot( @@ -166,19 +405,50 @@ class FlexibleTaskActionService { updatedAt: now, ), }; + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible push destination scheduling finished. ' + 'destination=${destination.name} taskId=$taskId ' + 'outcome=${result.outcomeCode.name} changeCount=${result.changes.length} ' + 'noticeCount=${result.notices.length}'); + } + if (_isHandledPushIssue(result.outcomeCode) && + logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Handled flexible push issue. ' + 'destination=${destination.name} taskId=$taskId ' + 'outcome=${result.outcomeCode.name} ' + 'notices=${_noticeSummary(result.notices)}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.fine)) { + logger.fine(() => 'Flexible push result details. ' + 'destination=${destination.name} taskId=$taskId ' + 'changes=${_changeSummary(result.changes)} ' + 'notices=${_noticeSummary(result.notices)}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Flexible push destination result dump. ' + 'destination=${destination.name} taskId=$taskId ' + 'tasks=${_taskListSummary(result.tasks)}'); + } + + final activities = _activitiesForPushDestination( + destination: destination, + input: input, + result: result, + taskId: taskId, + operationId: opId, + occurredAt: now, + existingActivities: existingActivities, + ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible push destination activities prepared. ' + 'destination=${destination.name} taskId=$taskId ' + 'activityCount=${activities.length}'); + } return PushDestinationResult( destination: destination, schedulingResult: result, - activities: _activitiesForPushDestination( - destination: destination, - input: input, - result: result, - taskId: taskId, - operationId: opId, - occurredAt: now, - existingActivities: existingActivities, - ), + activities: activities, ); } @@ -191,8 +461,22 @@ class FlexibleTaskActionService { required String taskId, DateTime? updatedAt, }) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger + .debug(() => 'Moving flexible task to backlog from push destination. ' + 'taskId=$taskId taskCount=${input.tasks.length} ' + 'hasExplicitUpdatedAt=${updatedAt != null}'); + } + if (logger.isEnabled(FlexibleTaskActionLogLevel.finest)) { + logger.finest(() => 'Move-to-backlog input dump. ' + 'taskId=$taskId tasks=${_taskListSummary(input.tasks)}'); + } final task = _taskById(input.tasks, taskId); if (task == null) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Handled move-to-backlog issue: task not found. ' + 'taskId=$taskId'); + } return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog, @@ -209,6 +493,11 @@ class FlexibleTaskActionService { } if (!task.isFlexible || task.status != TaskStatus.planned) { + if (logger.isEnabled(FlexibleTaskActionLogLevel.warn)) { + logger.warn(() => 'Handled move-to-backlog issue: invalid task state. ' + 'taskId=${task.id} taskType=${task.type.name} ' + 'taskStatus=${task.status.name}'); + } return SchedulingResult( tasks: input.tasks, operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog, @@ -228,6 +517,12 @@ class FlexibleTaskActionService { task, updatedAt: updatedAt, ); + if (logger.isEnabled(FlexibleTaskActionLogLevel.debug)) { + logger.debug(() => 'Flexible task moved to backlog. ' + 'taskId=${task.id} previousStart=${task.scheduledStart?.toIso8601String()} ' + 'previousEnd=${task.scheduledEnd?.toIso8601String()} ' + 'updatedAt=${updatedAt?.toIso8601String()}'); + } return SchedulingResult( tasks: List.unmodifiable( @@ -267,3 +562,122 @@ class FlexibleTaskActionService { ); } } + +/// Returns whether [level] should be emitted for [minimumLevel]. +bool _shouldWrite( + FlexibleTaskActionLogLevel level, + FlexibleTaskActionLogLevel minimumLevel, +) { + return _severity(level) >= _severity(minimumLevel); +} + +/// Converts [level] to a comparable severity value. +int _severity(FlexibleTaskActionLogLevel level) { + return switch (level) { + FlexibleTaskActionLogLevel.finest => 0, + FlexibleTaskActionLogLevel.finer => 1, + FlexibleTaskActionLogLevel.fine => 2, + FlexibleTaskActionLogLevel.debug => 3, + FlexibleTaskActionLogLevel.info => 4, + FlexibleTaskActionLogLevel.warn => 5, + FlexibleTaskActionLogLevel.error => 6, + }; +} + +/// Returns whether caller capture should run for [level]. +bool _shouldCaptureCaller({ + required FlexibleTaskActionLogLevel level, + required FlexibleTaskActionLogLevel minimumLevel, +}) { + if (minimumLevel == FlexibleTaskActionLogLevel.finest) { + return true; + } + final capturesWarningContext = level == FlexibleTaskActionLogLevel.warn || + level == FlexibleTaskActionLogLevel.error; + return capturesWarningContext && + _severity(minimumLevel) <= _severity(FlexibleTaskActionLogLevel.fine); +} + +/// Resolves a plain or lazy log [message]. +String _resolveLogMessage(Object? message) { + final resolved = + message is FlexibleTaskActionLogMessage ? message() : message; + return resolved?.toString().trim() ?? ''; +} + +/// Captures the first stack frame outside logger internals. +String _callerFrame() { + for (final line in StackTrace.current.toString().split('\n')) { + final trimmed = line.trim(); + if (trimmed.isEmpty || + trimmed.contains('_callerFrame') || + trimmed.contains('FlexibleTaskActionLogger.')) { + continue; + } + return trimmed.replaceAll('\n', r'\n'); + } + return 'unknown'; +} + +/// Returns whether [outcomeCode] represents a handled push issue. +bool _isHandledPushIssue(SchedulingOutcomeCode outcomeCode) { + return switch (outcomeCode) { + SchedulingOutcomeCode.success => false, + SchedulingOutcomeCode.noOp || + SchedulingOutcomeCode.notFound || + SchedulingOutcomeCode.invalidState || + SchedulingOutcomeCode.noSlot || + SchedulingOutcomeCode.overflow || + SchedulingOutcomeCode.conflict => + true, + }; +} + +/// Builds a compact summary for [notices]. +String _noticeSummary(List notices) { + if (notices.isEmpty) { + return 'none'; + } + return notices + .map((notice) => + '${notice.type.name}:${notice.issueCode?.name ?? notice.movementCode?.name ?? 'none'}') + .join(','); +} + +/// Builds a compact summary for [changes]. +String _changeSummary(List changes) { + if (changes.isEmpty) { + return 'none'; + } + return changes + .map((change) => + '${change.taskId}:${change.previousStart?.toIso8601String()}->${change.nextStart?.toIso8601String()}') + .join(','); +} + +/// Builds a compact dump for [tasks]. +String _taskListSummary(List tasks) { + if (tasks.isEmpty) { + return 'none'; + } + return tasks.map(_taskSummary).join(','); +} + +/// Builds a compact dump for [task]. +String _taskSummary(Task task) { + return '${task.id}{type=${task.type.name},status=${task.status.name},' + 'project=${task.projectId},duration=${task.durationMinutes},' + 'start=${task.scheduledStart?.toIso8601String()},' + 'end=${task.scheduledEnd?.toIso8601String()}}'; +} + +/// Builds a compact dump for [intervals]. +String _intervalSummary(List intervals) { + if (intervals.isEmpty) { + return 'none'; + } + return intervals + .map((interval) => + '${interval.start.toIso8601String()}-${interval.end.toIso8601String()}') + .join(','); +}