eva/focus-flow
6
0
Fork 1
Code Issues 14 Pull requests 1 Projects Releases Packages Wiki Activity Actions 1

refactor: centralize scheduler logging

Browse source
This commit is contained in:
Ashley Venn 2026-07-02 19:05:17 -07:00
parent d5f5fc1b8f
commit 507bee6ad1
8 changed files with 652 additions and 556 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

161
apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart
View file

@ -6,10 +6,9 @@ library;
import 'dart:io';
import 'focus_flow_runtime_config.dart';
import 'package:scheduler_core/scheduler_core.dart' as scheduler_core;
/// Lazily creates a log message only after the target level is enabled.
typedef FocusFlowLogMessage = Object? Function();
import 'focus_flow_runtime_config.dart';
/// Minimal append-only file logger for FocusFlow runtime diagnostics.
final class FocusFlowFileLogger {
@ -17,15 +16,21 @@ final class FocusFlowFileLogger {
FocusFlowFileLogger._({
required this.minimumLevel,
required this.logFilePath,
required this._now,
required this._logger,
});
/// Additional caller-frame marker for this app wrapper.
static const List<String> _callerFrameIgnores = <String>[
'focus_flow_file_logger.dart',
];
/// Creates a disabled logger that drops every message.
factory FocusFlowFileLogger.disabled({DateTime Function()? now}) {
scheduler_core.logger.disable(now: now);
return FocusFlowFileLogger._(
minimumLevel: null,
logFilePath: null,
now: now ?? _utcNow,
logger: scheduler_core.FocusFlowLogger.disabled(now: now),
);
}
@ -44,10 +49,24 @@ final class FocusFlowFileLogger {
try {
final directory = Directory(location);
await directory.create(recursive: true);
final logFilePath = _joinPath(directory.path, fileName);
final resolvedNow = now ?? _utcNow;
final sink = _fileSink(logFilePath);
scheduler_core.logger.configure(
minimumLevel: level,
sink: sink,
now: resolvedNow,
callerFrameIgnores: _callerFrameIgnores,
);
return FocusFlowFileLogger._(
minimumLevel: level,
logFilePath: _joinPath(directory.path, fileName),
now: now ?? _utcNow,
logFilePath: logFilePath,
logger: scheduler_core.FocusFlowLogger(
minimumLevel: level,
sink: sink,
now: resolvedNow,
callerFrameIgnores: _callerFrameIgnores,
),
);
} on Object {
return FocusFlowFileLogger.disabled(now: now);
@ -60,41 +79,41 @@ final class FocusFlowFileLogger {
/// Concrete file path receiving appended log lines.
final String? logFilePath;
/// Clock boundary used for log timestamps.
final DateTime Function() _now;
/// Shared logger implementation that owns gating and caller capture.
final scheduler_core.FocusFlowLogger _logger;
/// Whether this logger currently writes to a file.
bool get isEnabled => minimumLevel != null && logFilePath != null;
bool get isEnabled => logFilePath != null && _logger.isEnabled;
/// Writes a finest-level [message] when enabled for finest logging.
Future<void> finest(Object? message) {
return write(FocusFlowLogLevel.finest, message);
return write(scheduler_core.FocusFlowLogLevel.finest, message);
}
/// Writes a finer-level [message] when enabled for finer logging.
Future<void> finer(Object? message) {
return write(FocusFlowLogLevel.finer, message);
return write(scheduler_core.FocusFlowLogLevel.finer, message);
}
/// Writes a fine-level [message] when enabled for fine logging.
Future<void> fine(Object? message) {
return write(FocusFlowLogLevel.fine, message);
return write(scheduler_core.FocusFlowLogLevel.fine, message);
}
/// Writes a debug-level [message] when enabled for debug or lower.
Future<void> debug(Object? message) {
return write(FocusFlowLogLevel.debug, message);
return write(scheduler_core.FocusFlowLogLevel.debug, message);
}
/// Writes an info-level [message] when enabled for info or lower.
Future<void> info(Object? message) {
return write(FocusFlowLogLevel.info, message);
return write(scheduler_core.FocusFlowLogLevel.info, message);
}
/// Writes a warning-level [message] when enabled for warning or lower.
Future<void> warn(Object? message, {Object? error, StackTrace? stackTrace}) {
return write(
FocusFlowLogLevel.warn,
scheduler_core.FocusFlowLogLevel.warn,
message,
error: error,
stackTrace: stackTrace,
@ -104,7 +123,7 @@ final class FocusFlowFileLogger {
/// Writes an error-level [message] when file logging is enabled.
Future<void> error(Object? message, {Object? error, StackTrace? stackTrace}) {
return write(
FocusFlowLogLevel.error,
scheduler_core.FocusFlowLogLevel.error,
message,
error: error,
stackTrace: stackTrace,
@ -113,110 +132,28 @@ final class FocusFlowFileLogger {
/// Writes [message] at [level] when it passes the configured threshold.
Future<void> write(
FocusFlowLogLevel level,
scheduler_core.FocusFlowLogLevel level,
Object? message, {
Object? error,
StackTrace? stackTrace,
}) async {
final path = logFilePath;
final configuredLevel = minimumLevel;
if (path == null ||
configuredLevel == null ||
!_shouldWrite(level, configuredLevel)) {
return;
}) {
_logger.write(level, message, error: error, stackTrace: stackTrace);
return Future<void>.value();
}
final caller =
_shouldCaptureCaller(level: level, minimumLevel: configuredLevel)
? _callerFrame()
: null;
final resolvedMessage = _resolveMessage(message);
final buffer = StringBuffer()
..write(_now().toUtc().toIso8601String())
..write(' ')
..write(level.name.toUpperCase())
..write(' ');
if (caller != null) {
buffer
..write('caller=')
..write(caller)
..write(' ');
}
buffer.write(resolvedMessage);
if (error != null) {
buffer
..write(' | error=')
..write(error);
}
if (stackTrace != null) {
buffer
..write(' | stackTrace=')
..write(stackTrace.toString().replaceAll('\n', r'\n'));
}
buffer.writeln();
await File(
path,
).writeAsString(buffer.toString(), mode: FileMode.append, flush: true);
}
}
/// Returns whether [level] should be written for [minimumLevel].
bool _shouldWrite(FocusFlowLogLevel level, FocusFlowLogLevel minimumLevel) {
return _severity(level) >= _severity(minimumLevel);
}
/// Converts [level] to an ordered severity value.
int _severity(FocusFlowLogLevel level) {
return switch (level) {
FocusFlowLogLevel.finest => 0,
FocusFlowLogLevel.finer => 1,
FocusFlowLogLevel.fine => 2,
FocusFlowLogLevel.debug => 3,
FocusFlowLogLevel.info => 4,
FocusFlowLogLevel.warn => 5,
FocusFlowLogLevel.error => 6,
};
}
/// Whether automatic callsite capture should run for [level].
bool _shouldCaptureCaller({
required FocusFlowLogLevel level,
required FocusFlowLogLevel minimumLevel,
}) {
if (minimumLevel == FocusFlowLogLevel.finest) {
return true;
}
final capturesWarningContext =
level == FocusFlowLogLevel.warn || level == FocusFlowLogLevel.error;
return capturesWarningContext &&
_severity(minimumLevel) <= _severity(FocusFlowLogLevel.fine);
}
/// Resolves a plain or lazy message after level gating has passed.
String _resolveMessage(Object? message) {
final resolved = message is FocusFlowLogMessage ? message() : message;
return resolved?.toString().trim() ?? '';
}
/// Captures the first stack frame outside the logger implementation.
String _callerFrame() {
for (final line in StackTrace.current.toString().split('\n')) {
final trimmed = line.trim();
if (trimmed.isEmpty || trimmed.contains('focus_flow_file_logger.dart')) {
continue;
}
return _sanitizeForSingleLine(trimmed);
}
return 'unknown';
}
/// Returns the current UTC timestamp.
DateTime _utcNow() => DateTime.now().toUtc();
/// Keeps diagnostic text on one line for append-only file logs.
String _sanitizeForSingleLine(String value) {
return value.replaceAll('\n', r'\n');
/// Creates a file sink that appends formatted log entries.
scheduler_core.FocusFlowLogSink _fileSink(String path) {
return (entry) {
File(path).writeAsStringSync(
'${entry.toSingleLine()}\n',
mode: FileMode.append,
flush: true,
);
};
}
/// Joins [base] and [child] with the platform path separator.

45
apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart
View file

@ -7,6 +7,10 @@ library;
import 'dart:convert';
import 'dart:io';
import 'package:scheduler_core/scheduler_core.dart' show FocusFlowLogLevel;
export 'package:scheduler_core/scheduler_core.dart' show FocusFlowLogLevel;
/// File-backed runtime configuration for optional developer diagnostics.
final class FocusFlowRuntimeConfig {
/// Creates a runtime configuration with optional logging controls.
@ -67,47 +71,6 @@ final class FocusFlowRuntimeConfig {
bool get enablesFileLogging => logLevel != null && logFileLocation != null;
}
/// Supported FocusFlow file logging levels, ordered from most to least verbose.
enum FocusFlowLogLevel {
/// Logs every message with automatic callsite detail.
finest,
/// Logs intra-method minor actions and small state changes.
finer,
/// Logs secondary details, possible issues, and rich warning/error context.
fine,
/// Logs debug, info, warning, and error messages.
debug,
/// Logs normal operational information, warnings, and errors.
info,
/// Logs warnings and errors.
warn,
/// Logs only errors.
error;
/// Parses [value] into a supported logging level.
static FocusFlowLogLevel? tryParse(String? value) {
final normalized = value?.trim().toLowerCase();
if (normalized == null || normalized.isEmpty) {
return null;
}
if (normalized == 'trace') {
return finest;
}
for (final level in FocusFlowLogLevel.values) {
if (level.name == normalized) {
return level;
}
}
return null;
}
}
/// Reads [value] as a non-empty string when present.
String? _optionalString(Object? value) {
if (value is! String) {

3
apps/focus_flow_flutter/test/app/runtime_config_test.dart
View file

@ -10,9 +10,12 @@ import 'dart:io';
import 'package:flutter_test/flutter_test.dart';
import 'package:focus_flow_flutter/app/runtime/focus_flow_file_logger.dart';
import 'package:focus_flow_flutter/app/runtime/focus_flow_runtime_config.dart';
import 'package:scheduler_core/scheduler_core.dart' as scheduler_core;
/// Runs runtime config tests.
void main() {
tearDown(scheduler_core.logger.disable);
group('FocusFlowRuntimeConfig', () {
test('missing config file leaves optional settings unset', () async {
final directory = await Directory.systemTemp.createTemp(

1
packages/scheduler_core/lib/scheduler_core.dart
View file

@ -33,6 +33,7 @@ export 'src/persistence/document_mapping.dart';
export 'src/persistence/document_migration.dart';
export 'src/scheduling/free_slots.dart';
export 'src/domain/locked_time.dart';
export 'src/logging/focus_flow_logger.dart';
export 'src/domain/occupancy_policy.dart';
export 'src/persistence/persistence_contract.dart';
export 'src/domain/project_statistics.dart';

390
packages/scheduler_core/lib/src/logging/focus_flow_logger.dart Normal file
View file

@ -0,0 +1,390 @@
// SPDX-FileCopyrightText: 2026 FocusFlow contributors
// SPDX-License-Identifier: AGPL-3.0-only
/// Provides shared FocusFlow logging primitives for scheduler code.
library;
/// Lazily creates a log message after level gating passes.
typedef FocusFlowLogMessage = Object? Function();
/// Receives one enabled log entry.
typedef FocusFlowLogSink = void Function(FocusFlowLogEntry entry);
/// Shared process logger used by scheduler core code.
final FocusFlowLogger logger = FocusFlowLogger.disabled();
/// Supported FocusFlow logging levels, ordered from most to least verbose.
enum FocusFlowLogLevel {
/// Extremely granular diagnostics, data dumps, and caller details for every log.
finest,
/// Intra-method minor actions and small state changes.
finer,
/// Secondary details, possible issues, and rich warning/error context.
fine,
/// High-level debug flow and useful state values.
debug,
/// Very high-level operational checkpoints.
info,
/// Handled issues where the app recovered and kept going.
warn,
/// Invalid or unsafe states that need review.
error;
/// Parses [value] into a supported logging level.
static FocusFlowLogLevel? tryParse(String? value) {
final normalized = value?.trim().toLowerCase();
if (normalized == null || normalized.isEmpty) {
return null;
}
if (normalized == 'trace') {
return finest;
}
for (final level in FocusFlowLogLevel.values) {
if (level.name == normalized) {
return level;
}
}
return null;
}
/// Ordered severity used for threshold comparisons.
int get severity {
return switch (this) {
FocusFlowLogLevel.finest => 0,
FocusFlowLogLevel.finer => 1,
FocusFlowLogLevel.fine => 2,
FocusFlowLogLevel.debug => 3,
FocusFlowLogLevel.info => 4,
FocusFlowLogLevel.warn => 5,
FocusFlowLogLevel.error => 6,
};
}
/// Whether this level should write when [minimumLevel] is configured.
bool writesAt(FocusFlowLogLevel minimumLevel) {
return severity >= minimumLevel.severity;
}
}
/// Structured log entry produced after level gating has passed.
final class FocusFlowLogEntry {
/// Creates a structured log entry.
const FocusFlowLogEntry({
required this.timestamp,
required this.level,
required this.message,
this.caller,
this.error,
this.stackTrace,
});
/// UTC timestamp for the log event.
final DateTime timestamp;
/// Severity level for the log event.
final FocusFlowLogLevel level;
/// Resolved log message.
final String message;
/// Optional caller frame captured by [FocusFlowLogger].
final String? caller;
/// Optional error object attached to the entry.
final Object? error;
/// Optional stack trace attached to the entry.
final StackTrace? stackTrace;
/// Formats this entry as one append-only log line.
String toSingleLine() {
final buffer = StringBuffer()
..write(timestamp.toUtc().toIso8601String())
..write(' ')
..write(level.name.toUpperCase())
..write(' ');
final currentCaller = caller;
if (currentCaller != null) {
buffer
..write('caller=')
..write(_sanitizeForSingleLine(currentCaller))
..write(' ');
}
buffer.write(_sanitizeForSingleLine(message));
final currentError = error;
if (currentError != null) {
buffer
..write(' | error=')
..write(_sanitizeForSingleLine(currentError.toString()));
}
final currentStackTrace = stackTrace;
if (currentStackTrace != null) {
buffer
..write(' | stackTrace=')
..write(_sanitizeForSingleLine(currentStackTrace.toString()));
}
return buffer.toString();
}
}
/// Logger that handles level gating, lazy messages, and caller capture.
final class FocusFlowLogger {
/// Creates a logger with optional runtime configuration.
FocusFlowLogger({
FocusFlowLogLevel? minimumLevel,
FocusFlowLogSink? sink,
DateTime Function()? now,
Iterable<String> callerFrameIgnores = const <String>[],
}) : _minimumLevel = minimumLevel,
_sink = sink,
_now = now ?? _utcNow,
_callerFrameIgnores = _normalizedCallerFrameIgnores(
callerFrameIgnores,
);
/// Creates a logger that drops every message.
factory FocusFlowLogger.disabled({DateTime Function()? now}) {
return FocusFlowLogger(now: now);
}
/// Minimum level currently configured for this logger.
FocusFlowLogLevel? _minimumLevel;
/// Destination receiving enabled entries.
FocusFlowLogSink? _sink;
/// Clock used to timestamp log entries.
DateTime Function() _now;
/// Stack-frame markers ignored when capturing the caller.
List<String> _callerFrameIgnores;
/// Minimum level that will be written, or null when disabled.
FocusFlowLogLevel? get minimumLevel => _minimumLevel;
/// Whether this logger has enough configuration to write entries.
bool get isEnabled => _minimumLevel != null && _sink != null;
/// Replaces this logger's runtime configuration.
void configure({
required FocusFlowLogLevel minimumLevel,
required FocusFlowLogSink sink,
DateTime Function()? now,
Iterable<String> callerFrameIgnores = const <String>[],
}) {
_minimumLevel = minimumLevel;
_sink = sink;
_now = now ?? _utcNow;
_callerFrameIgnores = _normalizedCallerFrameIgnores(callerFrameIgnores);
}
/// Disables this logger and drops subsequent messages.
void disable({DateTime Function()? now}) {
_minimumLevel = null;
_sink = null;
_now = now ?? _utcNow;
_callerFrameIgnores = _normalizedCallerFrameIgnores(const <String>[]);
}
/// Whether [level] would currently be written.
bool wouldWrite(FocusFlowLogLevel level) {
final configured = _minimumLevel;
return configured != null && _sink != null && level.writesAt(configured);
}
/// Writes [message] at `finest` when enabled.
void finest(
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
write(
FocusFlowLogLevel.finest,
message,
error: error,
stackTrace: stackTrace,
);
}
/// Writes [message] at `finer` when enabled.
void finer(
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
write(
FocusFlowLogLevel.finer,
message,
error: error,
stackTrace: stackTrace,
);
}
/// Writes [message] at `fine` when enabled.
void fine(
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
write(
FocusFlowLogLevel.fine,
message,
error: error,
stackTrace: stackTrace,
);
}
/// Writes [message] at `debug` when enabled.
void debug(
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
write(
FocusFlowLogLevel.debug,
message,
error: error,
stackTrace: stackTrace,
);
}
/// Writes [message] at `info` when enabled.
void info(
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
write(
FocusFlowLogLevel.info,
message,
error: error,
stackTrace: stackTrace,
);
}
/// Writes [message] at `warn` when enabled.
void warn(
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
write(
FocusFlowLogLevel.warn,
message,
error: error,
stackTrace: stackTrace,
);
}
/// Writes [message] at `error` when enabled.
void error(
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
write(
FocusFlowLogLevel.error,
message,
error: error,
stackTrace: stackTrace,
);
}
/// Writes [message] at [level] when it passes the configured threshold.
void write(
FocusFlowLogLevel level,
Object? message, {
Object? error,
StackTrace? stackTrace,
}) {
final configured = _minimumLevel;
final currentSink = _sink;
if (configured == null ||
currentSink == null ||
!level.writesAt(configured)) {
return;
}
final entry = FocusFlowLogEntry(
timestamp: _now().toUtc(),
level: level,
message: _resolveMessage(message),
caller: _shouldCaptureCaller(level: level, minimumLevel: configured)
? _callerFrame()
: null,
error: error,
stackTrace: stackTrace,
);
try {
currentSink(entry);
} on Object {
return;
}
}
/// Captures the first stack frame outside known logging internals.
String _callerFrame() {
for (final line in StackTrace.current.toString().split('\n')) {
final trimmed = line.trim();
final shouldIgnore = _callerFrameIgnores.any(trimmed.contains);
if (trimmed.isEmpty || shouldIgnore) {
continue;
}
return _sanitizeForSingleLine(trimmed);
}
return 'unknown';
}
}
/// Returns whether caller capture should run for [level].
bool _shouldCaptureCaller({
required FocusFlowLogLevel level,
required FocusFlowLogLevel minimumLevel,
}) {
if (minimumLevel == FocusFlowLogLevel.finest) {
return true;
}
final capturesWarningContext =
level == FocusFlowLogLevel.warn || level == FocusFlowLogLevel.error;
return capturesWarningContext &&
minimumLevel.severity <= FocusFlowLogLevel.fine.severity;
}
/// Resolves a plain or lazy [message] after level gating passes.
String _resolveMessage(Object? message) {
try {
final resolved = message is FocusFlowLogMessage ? message() : message;
return resolved?.toString().trim() ?? '';
} on Object catch (error) {
return 'Log message evaluation failed: $error';
}
}
/// Returns the current UTC timestamp.
DateTime _utcNow() => DateTime.now().toUtc();
/// Builds the complete set of caller frame markers to skip.
List<String> _normalizedCallerFrameIgnores(
Iterable<String> callerFrameIgnores,
) {
final ignores = <String>{'focus_flow_logger.dart'};
for (final ignore in callerFrameIgnores) {
final trimmed = ignore.trim();
if (trimmed.isNotEmpty) {
ignores.add(trimmed);
}
}
return List<String>.unmodifiable(ignores);
}
/// Keeps diagnostic text on one physical log line.
String _sanitizeForSingleLine(String value) {
return value.replaceAll('\n', r'\n');
}

1
packages/scheduler_core/lib/src/scheduling/task_actions.dart
View file

@ -13,6 +13,7 @@ library;
import '../domain/models.dart';
import '../domain/occupancy_policy.dart';
import '../logging/focus_flow_logger.dart';
import 'scheduling_engine.dart';
import 'task_lifecycle.dart';
import '../domain/time_contracts.dart';

363
packages/scheduler_core/lib/src/scheduling/task_actions/services/flexible_task_action_service.dart
View file

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

118
packages/scheduler_core/test/focus_flow_logger_test.dart Normal file
View file

@ -0,0 +1,118 @@
// SPDX-FileCopyrightText: 2026 FocusFlow contributors
// SPDX-License-Identifier: AGPL-3.0-only
/// Tests shared FocusFlow logging behavior.
library;
import 'package:scheduler_core/scheduler_core.dart';
import 'package:test/test.dart';
/// Runs shared logger tests.
void main() {
tearDown(logger.disable);
group('FocusFlowLogLevel', () {
test('parses every supported level and trace alias', () {
expect(FocusFlowLogLevel.tryParse('finest'), FocusFlowLogLevel.finest);
expect(FocusFlowLogLevel.tryParse('finer'), FocusFlowLogLevel.finer);
expect(FocusFlowLogLevel.tryParse('fine'), FocusFlowLogLevel.fine);
expect(FocusFlowLogLevel.tryParse('debug'), FocusFlowLogLevel.debug);
expect(FocusFlowLogLevel.tryParse('info'), FocusFlowLogLevel.info);
expect(FocusFlowLogLevel.tryParse('warn'), FocusFlowLogLevel.warn);
expect(FocusFlowLogLevel.tryParse('error'), FocusFlowLogLevel.error);
expect(FocusFlowLogLevel.tryParse('trace'), FocusFlowLogLevel.finest);
expect(FocusFlowLogLevel.tryParse('verbose'), isNull);
});
});
group('FocusFlowLogger', () {
test('skips lazy messages below the configured level', () {
final entries = <FocusFlowLogEntry>[];
final testLogger = FocusFlowLogger(
minimumLevel: FocusFlowLogLevel.info,
sink: entries.add,
now: () => DateTime.utc(2026, 7, 3, 12),
);
var evaluated = false;
testLogger.debug(() {
evaluated = true;
return 'expensive debug state';
});
expect(evaluated, isFalse);
expect(entries, isEmpty);
});
test('writes enabled lazy messages with timestamps', () {
final entries = <FocusFlowLogEntry>[];
final testLogger = FocusFlowLogger(
minimumLevel: FocusFlowLogLevel.debug,
sink: entries.add,
now: () => DateTime.utc(2026, 7, 3, 12),
);
testLogger.debug(() => 'computed debug state');
expect(entries.single.level, FocusFlowLogLevel.debug);
expect(entries.single.timestamp, DateTime.utc(2026, 7, 3, 12));
expect(entries.single.message, 'computed debug state');
});
test('finest captures caller information for every written level', () {
final entries = <FocusFlowLogEntry>[];
final testLogger = FocusFlowLogger(
minimumLevel: FocusFlowLogLevel.finest,
sink: entries.add,
now: () => DateTime.utc(2026, 7, 3, 12),
);
testLogger.info('high level message');
expect(entries.single.caller, contains('focus_flow_logger_test.dart'));
});
test('fine captures caller information for warnings and errors', () {
final entries = <FocusFlowLogEntry>[];
final testLogger = FocusFlowLogger(
minimumLevel: FocusFlowLogLevel.fine,
sink: entries.add,
now: () => DateTime.utc(2026, 7, 3, 12),
);
testLogger.warn('handled warning');
expect(entries.single.caller, contains('focus_flow_logger_test.dart'));
});
test('info does not capture caller information for warnings', () {
final entries = <FocusFlowLogEntry>[];
final testLogger = FocusFlowLogger(
minimumLevel: FocusFlowLogLevel.info,
sink: entries.add,
now: () => DateTime.utc(2026, 7, 3, 12),
);
testLogger.warn('minimal warning');
expect(entries.single.caller, isNull);
});
test('formats errors and stack traces on a single line', () {
final entry = FocusFlowLogEntry(
timestamp: DateTime.utc(2026, 7, 3, 12),
level: FocusFlowLogLevel.error,
message: 'bad state',
caller: '#1 method (file.dart:10:2)',
error: 'boom',
stackTrace: StackTrace.fromString('first\nsecond'),
);
expect(
entry.toSingleLine(),
'2026-07-03T12:00:00.000Z ERROR caller=#1 method (file.dart:10:2) '
r'bad state | error=boom | stackTrace=first\nsecond',
);
});
});
}