feat: add flexible task action logging

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<TaskActivity> existingActivities = const <TaskActivity>[],
   }) {
     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,11 +405,32 @@ 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)}');
+    }
 
-    return PushDestinationResult(
+    final activities = _activitiesForPushDestination(
-      destination: destination,
-      schedulingResult: result,
-      activities: _activitiesForPushDestination(
       destination: destination,
       input: input,
       result: result,
@@ -178,7 +438,17 @@ class FlexibleTaskActionService {
       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: 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<Task>.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<SchedulingNotice> 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<SchedulingChange> 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<Task> 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<TimeInterval> intervals) {
+  if (intervals.isEmpty) {
+    return 'none';
+  }
+  return intervals
+      .map((interval) =>
+          '${interval.start.toIso8601String()}-${interval.end.toIso8601String()}')
+      .join(',');
+}