Merge branch 'app-config-file-logging' into task-pushing-01-past-task-controls
This commit is contained in:
commit
4183cb95ee
9 changed files with 842 additions and 111 deletions
|
|
@ -51,16 +51,30 @@ Supported optional keys:
|
||||||
|
|
||||||
```json
|
```json
|
||||||
{
|
{
|
||||||
"LogLevel": "debug",
|
"LogLevel": "fine",
|
||||||
"LogfileLocation": "~/ADHD_Scheduler/debug/"
|
"LogfileLocation": "~/ADHD_Scheduler/debug/"
|
||||||
}
|
}
|
||||||
```
|
```
|
||||||
|
|
||||||
`LogLevel` accepts `trace`, `debug`, `info`, `warn`, or `error`.
|
`LogLevel` accepts `finest`, `finer`, `fine`, `debug`, `info`, `warn`, or
|
||||||
|
`error`.
|
||||||
`LogfileLocation` is treated as a directory, and the app writes
|
`LogfileLocation` is treated as a directory, and the app writes
|
||||||
`focus_flow.log` inside it. If either key is absent or invalid, file logging is
|
`focus_flow.log` inside it. If either key is absent or invalid, file logging is
|
||||||
not enabled and the app ignores that setting.
|
not enabled and the app ignores that setting.
|
||||||
|
|
||||||
|
Verbose log levels can include automatic caller information without requiring
|
||||||
|
each call site to pass it manually. `finest` includes caller frames for every
|
||||||
|
written message. `fine`, `finer`, and `finest` include caller frames for
|
||||||
|
warnings and errors. This caller lookup is skipped when the configured level
|
||||||
|
does not require it.
|
||||||
|
|
||||||
|
For expensive debug/detail messages, pass a lazy closure so work is skipped when
|
||||||
|
the configured level would not write the log:
|
||||||
|
|
||||||
|
```dart
|
||||||
|
logger.debug(() => 'state=${expensiveStateDump()}');
|
||||||
|
```
|
||||||
|
|
||||||
## Package Boundary
|
## Package Boundary
|
||||||
|
|
||||||
Allowed app imports include public scheduler APIs such as:
|
Allowed app imports include public scheduler APIs such as:
|
||||||
|
|
|
||||||
|
|
@ -6,6 +6,8 @@ library;
|
||||||
|
|
||||||
import 'dart:io';
|
import 'dart:io';
|
||||||
|
|
||||||
|
import 'package:scheduler_core/scheduler_core.dart' as scheduler_core;
|
||||||
|
|
||||||
import 'focus_flow_runtime_config.dart';
|
import 'focus_flow_runtime_config.dart';
|
||||||
|
|
||||||
/// Minimal append-only file logger for FocusFlow runtime diagnostics.
|
/// Minimal append-only file logger for FocusFlow runtime diagnostics.
|
||||||
|
|
@ -14,15 +16,21 @@ final class FocusFlowFileLogger {
|
||||||
FocusFlowFileLogger._({
|
FocusFlowFileLogger._({
|
||||||
required this.minimumLevel,
|
required this.minimumLevel,
|
||||||
required this.logFilePath,
|
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.
|
/// Creates a disabled logger that drops every message.
|
||||||
factory FocusFlowFileLogger.disabled({DateTime Function()? now}) {
|
factory FocusFlowFileLogger.disabled({DateTime Function()? now}) {
|
||||||
|
scheduler_core.logger.disable(now: now);
|
||||||
return FocusFlowFileLogger._(
|
return FocusFlowFileLogger._(
|
||||||
minimumLevel: null,
|
minimumLevel: null,
|
||||||
logFilePath: null,
|
logFilePath: null,
|
||||||
now: now ?? _utcNow,
|
logger: scheduler_core.FocusFlowLogger.disabled(now: now),
|
||||||
);
|
);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|
@ -41,10 +49,24 @@ final class FocusFlowFileLogger {
|
||||||
try {
|
try {
|
||||||
final directory = Directory(location);
|
final directory = Directory(location);
|
||||||
await directory.create(recursive: true);
|
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._(
|
return FocusFlowFileLogger._(
|
||||||
minimumLevel: level,
|
minimumLevel: level,
|
||||||
logFilePath: _joinPath(directory.path, fileName),
|
logFilePath: logFilePath,
|
||||||
now: now ?? _utcNow,
|
logger: scheduler_core.FocusFlowLogger(
|
||||||
|
minimumLevel: level,
|
||||||
|
sink: sink,
|
||||||
|
now: resolvedNow,
|
||||||
|
callerFrameIgnores: _callerFrameIgnores,
|
||||||
|
),
|
||||||
);
|
);
|
||||||
} on Object {
|
} on Object {
|
||||||
return FocusFlowFileLogger.disabled(now: now);
|
return FocusFlowFileLogger.disabled(now: now);
|
||||||
|
|
@ -57,31 +79,41 @@ final class FocusFlowFileLogger {
|
||||||
/// Concrete file path receiving appended log lines.
|
/// Concrete file path receiving appended log lines.
|
||||||
final String? logFilePath;
|
final String? logFilePath;
|
||||||
|
|
||||||
/// Clock boundary used for log timestamps.
|
/// Shared logger implementation that owns gating and caller capture.
|
||||||
final DateTime Function() _now;
|
final scheduler_core.FocusFlowLogger _logger;
|
||||||
|
|
||||||
/// Whether this logger currently writes to a file.
|
/// Whether this logger currently writes to a file.
|
||||||
bool get isEnabled => minimumLevel != null && logFilePath != null;
|
bool get isEnabled => logFilePath != null && _logger.isEnabled;
|
||||||
|
|
||||||
/// Writes a trace-level [message] when enabled for trace.
|
/// Writes a finest-level [message] when enabled for finest logging.
|
||||||
Future<void> trace(String message) {
|
Future<void> finest(Object? message) {
|
||||||
return write(FocusFlowLogLevel.trace, 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(scheduler_core.FocusFlowLogLevel.finer, message);
|
||||||
|
}
|
||||||
|
|
||||||
|
/// Writes a fine-level [message] when enabled for fine logging.
|
||||||
|
Future<void> fine(Object? message) {
|
||||||
|
return write(scheduler_core.FocusFlowLogLevel.fine, message);
|
||||||
}
|
}
|
||||||
|
|
||||||
/// Writes a debug-level [message] when enabled for debug or lower.
|
/// Writes a debug-level [message] when enabled for debug or lower.
|
||||||
Future<void> debug(String message) {
|
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.
|
/// Writes an info-level [message] when enabled for info or lower.
|
||||||
Future<void> info(String message) {
|
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.
|
/// Writes a warning-level [message] when enabled for warning or lower.
|
||||||
Future<void> warn(String message, {Object? error, StackTrace? stackTrace}) {
|
Future<void> warn(Object? message, {Object? error, StackTrace? stackTrace}) {
|
||||||
return write(
|
return write(
|
||||||
FocusFlowLogLevel.warn,
|
scheduler_core.FocusFlowLogLevel.warn,
|
||||||
message,
|
message,
|
||||||
error: error,
|
error: error,
|
||||||
stackTrace: stackTrace,
|
stackTrace: stackTrace,
|
||||||
|
|
@ -89,9 +121,9 @@ final class FocusFlowFileLogger {
|
||||||
}
|
}
|
||||||
|
|
||||||
/// Writes an error-level [message] when file logging is enabled.
|
/// Writes an error-level [message] when file logging is enabled.
|
||||||
Future<void> error(String message, {Object? error, StackTrace? stackTrace}) {
|
Future<void> error(Object? message, {Object? error, StackTrace? stackTrace}) {
|
||||||
return write(
|
return write(
|
||||||
FocusFlowLogLevel.error,
|
scheduler_core.FocusFlowLogLevel.error,
|
||||||
message,
|
message,
|
||||||
error: error,
|
error: error,
|
||||||
stackTrace: stackTrace,
|
stackTrace: stackTrace,
|
||||||
|
|
@ -100,62 +132,30 @@ final class FocusFlowFileLogger {
|
||||||
|
|
||||||
/// Writes [message] at [level] when it passes the configured threshold.
|
/// Writes [message] at [level] when it passes the configured threshold.
|
||||||
Future<void> write(
|
Future<void> write(
|
||||||
FocusFlowLogLevel level,
|
scheduler_core.FocusFlowLogLevel level,
|
||||||
String message, {
|
Object? message, {
|
||||||
Object? error,
|
Object? error,
|
||||||
StackTrace? stackTrace,
|
StackTrace? stackTrace,
|
||||||
}) async {
|
}) {
|
||||||
final path = logFilePath;
|
_logger.write(level, message, error: error, stackTrace: stackTrace);
|
||||||
final configuredLevel = minimumLevel;
|
return Future<void>.value();
|
||||||
if (path == null ||
|
|
||||||
configuredLevel == null ||
|
|
||||||
!_shouldWrite(level, configuredLevel)) {
|
|
||||||
return;
|
|
||||||
}
|
}
|
||||||
|
|
||||||
final buffer = StringBuffer()
|
|
||||||
..write(_now().toUtc().toIso8601String())
|
|
||||||
..write(' ')
|
|
||||||
..write(level.name.toUpperCase())
|
|
||||||
..write(' ')
|
|
||||||
..write(message.trim());
|
|
||||||
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.trace => 0,
|
|
||||||
FocusFlowLogLevel.debug => 1,
|
|
||||||
FocusFlowLogLevel.info => 2,
|
|
||||||
FocusFlowLogLevel.warn => 3,
|
|
||||||
FocusFlowLogLevel.error => 4,
|
|
||||||
};
|
|
||||||
}
|
}
|
||||||
|
|
||||||
/// Returns the current UTC timestamp.
|
/// Returns the current UTC timestamp.
|
||||||
DateTime _utcNow() => DateTime.now().toUtc();
|
DateTime _utcNow() => DateTime.now().toUtc();
|
||||||
|
|
||||||
|
/// 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.
|
/// Joins [base] and [child] with the platform path separator.
|
||||||
String _joinPath(String base, String child) {
|
String _joinPath(String base, String child) {
|
||||||
if (base.endsWith('/') || base.endsWith(r'\')) {
|
if (base.endsWith('/') || base.endsWith(r'\')) {
|
||||||
|
|
|
||||||
|
|
@ -7,6 +7,10 @@ library;
|
||||||
import 'dart:convert';
|
import 'dart:convert';
|
||||||
import 'dart:io';
|
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.
|
/// File-backed runtime configuration for optional developer diagnostics.
|
||||||
final class FocusFlowRuntimeConfig {
|
final class FocusFlowRuntimeConfig {
|
||||||
/// Creates a runtime configuration with optional logging controls.
|
/// Creates a runtime configuration with optional logging controls.
|
||||||
|
|
@ -67,38 +71,6 @@ final class FocusFlowRuntimeConfig {
|
||||||
bool get enablesFileLogging => logLevel != null && logFileLocation != null;
|
bool get enablesFileLogging => logLevel != null && logFileLocation != null;
|
||||||
}
|
}
|
||||||
|
|
||||||
/// Supported FocusFlow file logging levels.
|
|
||||||
enum FocusFlowLogLevel {
|
|
||||||
/// Logs every message, including trace-level detail.
|
|
||||||
trace,
|
|
||||||
|
|
||||||
/// 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;
|
|
||||||
}
|
|
||||||
for (final level in FocusFlowLogLevel.values) {
|
|
||||||
if (level.name == normalized) {
|
|
||||||
return level;
|
|
||||||
}
|
|
||||||
}
|
|
||||||
return null;
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
/// Reads [value] as a non-empty string when present.
|
/// Reads [value] as a non-empty string when present.
|
||||||
String? _optionalString(Object? value) {
|
String? _optionalString(Object? value) {
|
||||||
if (value is! String) {
|
if (value is! String) {
|
||||||
|
|
|
||||||
|
|
@ -10,9 +10,12 @@ import 'dart:io';
|
||||||
import 'package:flutter_test/flutter_test.dart';
|
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_file_logger.dart';
|
||||||
import 'package:focus_flow_flutter/app/runtime/focus_flow_runtime_config.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.
|
/// Runs runtime config tests.
|
||||||
void main() {
|
void main() {
|
||||||
|
tearDown(scheduler_core.logger.disable);
|
||||||
|
|
||||||
group('FocusFlowRuntimeConfig', () {
|
group('FocusFlowRuntimeConfig', () {
|
||||||
test('missing config file leaves optional settings unset', () async {
|
test('missing config file leaves optional settings unset', () async {
|
||||||
final directory = await Directory.systemTemp.createTemp(
|
final directory = await Directory.systemTemp.createTemp(
|
||||||
|
|
@ -38,16 +41,26 @@ void main() {
|
||||||
'${directory.path}${Platform.pathSeparator}config.json',
|
'${directory.path}${Platform.pathSeparator}config.json',
|
||||||
);
|
);
|
||||||
await configFile.writeAsString(
|
await configFile.writeAsString(
|
||||||
jsonEncode({'LogLevel': 'trace', 'LogfileLocation': directory.path}),
|
jsonEncode({'LogLevel': 'finest', 'LogfileLocation': directory.path}),
|
||||||
);
|
);
|
||||||
|
|
||||||
final config = await FocusFlowRuntimeConfig.load(path: configFile.path);
|
final config = await FocusFlowRuntimeConfig.load(path: configFile.path);
|
||||||
|
|
||||||
expect(config.logLevel, FocusFlowLogLevel.trace);
|
expect(config.logLevel, FocusFlowLogLevel.finest);
|
||||||
expect(config.logFileLocation, directory.path);
|
expect(config.logFileLocation, directory.path);
|
||||||
expect(config.enablesFileLogging, isTrue);
|
expect(config.enablesFileLogging, isTrue);
|
||||||
});
|
});
|
||||||
|
|
||||||
|
test('parses every supported log level', () {
|
||||||
|
expect(FocusFlowLogLevel.tryParse('finest'), FocusFlowLogLevel.finest);
|
||||||
|
expect(FocusFlowLogLevel.tryParse('finer'), FocusFlowLogLevel.finer);
|
||||||
|
expect(FocusFlowLogLevel.tryParse('fine'), FocusFlowLogLevel.fine);
|
||||||
|
expect(FocusFlowLogLevel.tryParse('debug'), FocusFlowLogLevel.debug);
|
||||||
|
expect(FocusFlowLogLevel.tryParse('info'), FocusFlowLogLevel.info);
|
||||||
|
expect(FocusFlowLogLevel.tryParse('warn'), FocusFlowLogLevel.warn);
|
||||||
|
expect(FocusFlowLogLevel.tryParse('error'), FocusFlowLogLevel.error);
|
||||||
|
});
|
||||||
|
|
||||||
test('loads supported logging settings from JSON', () {
|
test('loads supported logging settings from JSON', () {
|
||||||
final config = FocusFlowRuntimeConfig.fromJson({
|
final config = FocusFlowRuntimeConfig.fromJson({
|
||||||
'LogLevel': 'debug',
|
'LogLevel': 'debug',
|
||||||
|
|
@ -107,5 +120,130 @@ void main() {
|
||||||
expect(contents, contains('written warning'));
|
expect(contents, contains('written warning'));
|
||||||
expect(contents, contains('ERROR written error | error=boom'));
|
expect(contents, contains('ERROR written error | error=boom'));
|
||||||
});
|
});
|
||||||
|
|
||||||
|
test('skips lazy message work below the configured level', () async {
|
||||||
|
final directory = await Directory.systemTemp.createTemp(
|
||||||
|
'focus-flow-lazy-skip-test-',
|
||||||
|
);
|
||||||
|
addTearDown(() => directory.delete(recursive: true));
|
||||||
|
final logger = await FocusFlowFileLogger.open(
|
||||||
|
FocusFlowRuntimeConfig(
|
||||||
|
logLevel: FocusFlowLogLevel.info,
|
||||||
|
logFileLocation: directory.path,
|
||||||
|
),
|
||||||
|
);
|
||||||
|
var evaluated = false;
|
||||||
|
|
||||||
|
await logger.debug(() {
|
||||||
|
evaluated = true;
|
||||||
|
return 'expensive debug state';
|
||||||
|
});
|
||||||
|
|
||||||
|
expect(evaluated, isFalse);
|
||||||
|
expect(
|
||||||
|
File(
|
||||||
|
'${directory.path}${Platform.pathSeparator}focus_flow.log',
|
||||||
|
).existsSync(),
|
||||||
|
isFalse,
|
||||||
|
);
|
||||||
|
});
|
||||||
|
|
||||||
|
test('evaluates lazy messages once the level is enabled', () async {
|
||||||
|
final directory = await Directory.systemTemp.createTemp(
|
||||||
|
'focus-flow-lazy-write-test-',
|
||||||
|
);
|
||||||
|
addTearDown(() => directory.delete(recursive: true));
|
||||||
|
final logger = await FocusFlowFileLogger.open(
|
||||||
|
FocusFlowRuntimeConfig(
|
||||||
|
logLevel: FocusFlowLogLevel.debug,
|
||||||
|
logFileLocation: directory.path,
|
||||||
|
),
|
||||||
|
now: () => DateTime.utc(2026, 7, 3, 12),
|
||||||
|
);
|
||||||
|
var evaluations = 0;
|
||||||
|
|
||||||
|
await logger.debug(() {
|
||||||
|
evaluations += 1;
|
||||||
|
return 'computed debug state';
|
||||||
|
});
|
||||||
|
|
||||||
|
expect(evaluations, 1);
|
||||||
|
final contents = await File(
|
||||||
|
'${directory.path}${Platform.pathSeparator}focus_flow.log',
|
||||||
|
).readAsString();
|
||||||
|
expect(contents, contains('DEBUG computed debug state'));
|
||||||
|
});
|
||||||
|
|
||||||
|
test(
|
||||||
|
'finest captures caller information for every written level',
|
||||||
|
() async {
|
||||||
|
final directory = await Directory.systemTemp.createTemp(
|
||||||
|
'focus-flow-finest-caller-test-',
|
||||||
|
);
|
||||||
|
addTearDown(() => directory.delete(recursive: true));
|
||||||
|
final logger = await FocusFlowFileLogger.open(
|
||||||
|
FocusFlowRuntimeConfig(
|
||||||
|
logLevel: FocusFlowLogLevel.finest,
|
||||||
|
logFileLocation: directory.path,
|
||||||
|
),
|
||||||
|
now: () => DateTime.utc(2026, 7, 3, 12),
|
||||||
|
);
|
||||||
|
|
||||||
|
await logger.info('high level message');
|
||||||
|
|
||||||
|
final contents = await File(
|
||||||
|
'${directory.path}${Platform.pathSeparator}focus_flow.log',
|
||||||
|
).readAsString();
|
||||||
|
expect(contents, contains('INFO caller='));
|
||||||
|
expect(contents, contains('runtime_config_test.dart'));
|
||||||
|
expect(contents, contains('high level message'));
|
||||||
|
},
|
||||||
|
);
|
||||||
|
|
||||||
|
test('fine captures caller information for warnings and errors', () async {
|
||||||
|
final directory = await Directory.systemTemp.createTemp(
|
||||||
|
'focus-flow-fine-caller-test-',
|
||||||
|
);
|
||||||
|
addTearDown(() => directory.delete(recursive: true));
|
||||||
|
final logger = await FocusFlowFileLogger.open(
|
||||||
|
FocusFlowRuntimeConfig(
|
||||||
|
logLevel: FocusFlowLogLevel.fine,
|
||||||
|
logFileLocation: directory.path,
|
||||||
|
),
|
||||||
|
now: () => DateTime.utc(2026, 7, 3, 12),
|
||||||
|
);
|
||||||
|
|
||||||
|
await logger.warn('handled warning');
|
||||||
|
|
||||||
|
final contents = await File(
|
||||||
|
'${directory.path}${Platform.pathSeparator}focus_flow.log',
|
||||||
|
).readAsString();
|
||||||
|
expect(contents, contains('WARN caller='));
|
||||||
|
expect(contents, contains('runtime_config_test.dart'));
|
||||||
|
expect(contents, contains('handled warning'));
|
||||||
|
});
|
||||||
|
|
||||||
|
test('info does not capture caller information for warnings', () async {
|
||||||
|
final directory = await Directory.systemTemp.createTemp(
|
||||||
|
'focus-flow-info-caller-test-',
|
||||||
|
);
|
||||||
|
addTearDown(() => directory.delete(recursive: true));
|
||||||
|
final logger = await FocusFlowFileLogger.open(
|
||||||
|
FocusFlowRuntimeConfig(
|
||||||
|
logLevel: FocusFlowLogLevel.info,
|
||||||
|
logFileLocation: directory.path,
|
||||||
|
),
|
||||||
|
now: () => DateTime.utc(2026, 7, 3, 12),
|
||||||
|
);
|
||||||
|
|
||||||
|
await logger.warn('minimal warning');
|
||||||
|
|
||||||
|
final contents = await File(
|
||||||
|
'${directory.path}${Platform.pathSeparator}focus_flow.log',
|
||||||
|
).readAsString();
|
||||||
|
expect(contents, contains('WARN minimal warning'));
|
||||||
|
expect(contents, isNot(contains('caller=')));
|
||||||
|
expect(contents, isNot(contains('runtime_config_test.dart')));
|
||||||
|
});
|
||||||
});
|
});
|
||||||
}
|
}
|
||||||
|
|
|
||||||
|
|
@ -33,6 +33,7 @@ export 'src/persistence/document_mapping.dart';
|
||||||
export 'src/persistence/document_migration.dart';
|
export 'src/persistence/document_migration.dart';
|
||||||
export 'src/scheduling/free_slots.dart';
|
export 'src/scheduling/free_slots.dart';
|
||||||
export 'src/domain/locked_time.dart';
|
export 'src/domain/locked_time.dart';
|
||||||
|
export 'src/logging/focus_flow_logger.dart';
|
||||||
export 'src/domain/occupancy_policy.dart';
|
export 'src/domain/occupancy_policy.dart';
|
||||||
export 'src/persistence/persistence_contract.dart';
|
export 'src/persistence/persistence_contract.dart';
|
||||||
export 'src/domain/project_statistics.dart';
|
export 'src/domain/project_statistics.dart';
|
||||||
|
|
|
||||||
390
packages/scheduler_core/lib/src/logging/focus_flow_logger.dart
Normal file
390
packages/scheduler_core/lib/src/logging/focus_flow_logger.dart
Normal 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');
|
||||||
|
}
|
||||||
|
|
@ -13,6 +13,7 @@ library;
|
||||||
|
|
||||||
import '../domain/models.dart';
|
import '../domain/models.dart';
|
||||||
import '../domain/occupancy_policy.dart';
|
import '../domain/occupancy_policy.dart';
|
||||||
|
import '../logging/focus_flow_logger.dart';
|
||||||
import 'scheduling_engine.dart';
|
import 'scheduling_engine.dart';
|
||||||
import 'task_lifecycle.dart';
|
import 'task_lifecycle.dart';
|
||||||
import '../domain/time_contracts.dart';
|
import '../domain/time_contracts.dart';
|
||||||
|
|
|
||||||
|
|
@ -43,15 +43,35 @@ class FlexibleTaskActionService {
|
||||||
Iterable<TaskActivity> existingActivities = const <TaskActivity>[],
|
Iterable<TaskActivity> existingActivities = const <TaskActivity>[],
|
||||||
}) {
|
}) {
|
||||||
if (!task.isFlexible) {
|
if (!task.isFlexible) {
|
||||||
|
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(
|
throw ArgumentError.value(
|
||||||
task.type, 'task.type', 'Task must be flexible.');
|
task.type, 'task.type', 'Task must be flexible.');
|
||||||
}
|
}
|
||||||
|
|
||||||
|
logger.debug(() => 'Applying flexible quick action. '
|
||||||
|
'action=${action.name} taskId=${task.id} '
|
||||||
|
'taskStatus=${task.status.name} hasExplicitUpdatedAt=${updatedAt != null} '
|
||||||
|
'hasOperationId=${operationId != null}');
|
||||||
|
logger.finest(() => 'Flexible quick action input dump. '
|
||||||
|
'action=${action.name} task=$task '
|
||||||
|
'updatedAt=${updatedAt?.toIso8601String()} operationId=$operationId '
|
||||||
|
'actualStart=${actualStart?.toIso8601String()} '
|
||||||
|
'actualEnd=${actualEnd?.toIso8601String()} '
|
||||||
|
'lockedIntervals=$lockedIntervals '
|
||||||
|
'existingActivityCount=${existingActivities.length}');
|
||||||
|
|
||||||
switch (action) {
|
switch (action) {
|
||||||
case FlexibleTaskQuickAction.done:
|
case FlexibleTaskQuickAction.done:
|
||||||
final now = updatedAt ?? clock.now();
|
final now = updatedAt ?? clock.now();
|
||||||
final opId =
|
final opId =
|
||||||
operationId ?? _defaultOperationId(action.name, task.id, now);
|
operationId ?? _defaultOperationId(action.name, task.id, now);
|
||||||
|
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(
|
final transition = transitionService.apply(
|
||||||
task: task,
|
task: task,
|
||||||
transitionCode: TaskTransitionCode.complete,
|
transitionCode: TaskTransitionCode.complete,
|
||||||
|
|
@ -67,6 +87,17 @@ class FlexibleTaskActionService {
|
||||||
lockedIntervals: lockedIntervals,
|
lockedIntervals: lockedIntervals,
|
||||||
existingActivities: existingActivities,
|
existingActivities: existingActivities,
|
||||||
);
|
);
|
||||||
|
logger.debug(() => 'Flexible task completion transition finished. '
|
||||||
|
'taskId=${task.id} outcome=${transition.outcomeCode.name} '
|
||||||
|
'nextStatus=${transition.task.status.name} '
|
||||||
|
'activityCount=${transition.activities.length}');
|
||||||
|
if (transition.outcomeCode != TaskTransitionOutcomeCode.applied) {
|
||||||
|
logger
|
||||||
|
.fine(() => 'Possible issue: flexible completion did not apply. '
|
||||||
|
'taskId=${task.id} outcome=${transition.outcomeCode.name} '
|
||||||
|
'previousStatus=${task.status.name} '
|
||||||
|
'nextStatus=${transition.task.status.name}');
|
||||||
|
}
|
||||||
return FlexibleTaskActionResult(
|
return FlexibleTaskActionResult(
|
||||||
action: action,
|
action: action,
|
||||||
task: transition.task,
|
task: transition.task,
|
||||||
|
|
@ -74,6 +105,10 @@ class FlexibleTaskActionService {
|
||||||
transitionOutcomeCode: transition.outcomeCode,
|
transitionOutcomeCode: transition.outcomeCode,
|
||||||
);
|
);
|
||||||
case FlexibleTaskQuickAction.push:
|
case FlexibleTaskQuickAction.push:
|
||||||
|
logger.debug(() => 'Flexible push destination menu requested. '
|
||||||
|
'taskId=${task.id} taskStatus=${task.status.name}');
|
||||||
|
logger.finer(() => 'Flexible push destinations prepared. '
|
||||||
|
'taskId=${task.id} destinationCount=3');
|
||||||
return FlexibleTaskActionResult(
|
return FlexibleTaskActionResult(
|
||||||
action: action,
|
action: action,
|
||||||
task: task,
|
task: task,
|
||||||
|
|
@ -87,6 +122,10 @@ class FlexibleTaskActionService {
|
||||||
final now = updatedAt ?? clock.now();
|
final now = updatedAt ?? clock.now();
|
||||||
final opId =
|
final opId =
|
||||||
operationId ?? _defaultOperationId(action.name, task.id, now);
|
operationId ?? _defaultOperationId(action.name, task.id, now);
|
||||||
|
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(
|
final transition = transitionService.apply(
|
||||||
task: task,
|
task: task,
|
||||||
transitionCode: TaskTransitionCode.moveToBacklog,
|
transitionCode: TaskTransitionCode.moveToBacklog,
|
||||||
|
|
@ -99,6 +138,17 @@ class FlexibleTaskActionService {
|
||||||
occurredAt: now,
|
occurredAt: now,
|
||||||
existingActivities: existingActivities,
|
existingActivities: existingActivities,
|
||||||
);
|
);
|
||||||
|
logger.debug(() => 'Flexible task backlog transition finished. '
|
||||||
|
'taskId=${task.id} outcome=${transition.outcomeCode.name} '
|
||||||
|
'nextStatus=${transition.task.status.name} '
|
||||||
|
'activityCount=${transition.activities.length}');
|
||||||
|
if (transition.outcomeCode != TaskTransitionOutcomeCode.applied) {
|
||||||
|
logger.fine(() =>
|
||||||
|
'Possible issue: move-to-backlog quick action did not apply. '
|
||||||
|
'taskId=${task.id} outcome=${transition.outcomeCode.name} '
|
||||||
|
'previousStatus=${task.status.name} '
|
||||||
|
'nextStatus=${transition.task.status.name}');
|
||||||
|
}
|
||||||
return FlexibleTaskActionResult(
|
return FlexibleTaskActionResult(
|
||||||
action: action,
|
action: action,
|
||||||
task: transition.task,
|
task: transition.task,
|
||||||
|
|
@ -106,6 +156,8 @@ class FlexibleTaskActionService {
|
||||||
transitionOutcomeCode: transition.outcomeCode,
|
transitionOutcomeCode: transition.outcomeCode,
|
||||||
);
|
);
|
||||||
case FlexibleTaskQuickAction.breakUp:
|
case FlexibleTaskQuickAction.breakUp:
|
||||||
|
logger.debug(() => 'Flexible break-up flow requested. '
|
||||||
|
'taskId=${task.id} taskStatus=${task.status.name}');
|
||||||
return FlexibleTaskActionResult(
|
return FlexibleTaskActionResult(
|
||||||
action: action,
|
action: action,
|
||||||
task: task,
|
task: task,
|
||||||
|
|
@ -130,11 +182,21 @@ class FlexibleTaskActionService {
|
||||||
final now = updatedAt ?? clock.now();
|
final now = updatedAt ?? clock.now();
|
||||||
final opId = operationId ??
|
final opId = operationId ??
|
||||||
_defaultOperationId('push-${destination.name}', taskId, now);
|
_defaultOperationId('push-${destination.name}', taskId, now);
|
||||||
|
logger.debug(() => 'Applying flexible push destination. '
|
||||||
|
'destination=${destination.name} taskId=$taskId operationId=$opId '
|
||||||
|
'occurredAt=${now.toIso8601String()} taskCount=${input.tasks.length} '
|
||||||
|
'windowStart=${input.window.start.toIso8601String()} '
|
||||||
|
'windowEnd=${input.window.end.toIso8601String()}');
|
||||||
|
logger.finest(() => 'Flexible push destination input dump. '
|
||||||
|
'destination=${destination.name} taskId=$taskId input=$input '
|
||||||
|
'existingActivityCount=${existingActivities.length}');
|
||||||
if (_hasDuplicateActivity(
|
if (_hasDuplicateActivity(
|
||||||
existingActivities: existingActivities,
|
existingActivities: existingActivities,
|
||||||
operationId: opId,
|
operationId: opId,
|
||||||
taskId: taskId,
|
taskId: taskId,
|
||||||
)) {
|
)) {
|
||||||
|
logger.warn(() => 'Duplicate flexible push operation ignored. '
|
||||||
|
'destination=${destination.name} taskId=$taskId operationId=$opId');
|
||||||
return PushDestinationResult(
|
return PushDestinationResult(
|
||||||
destination: destination,
|
destination: destination,
|
||||||
schedulingResult: SchedulingResult(
|
schedulingResult: SchedulingResult(
|
||||||
|
|
@ -148,6 +210,8 @@ class FlexibleTaskActionService {
|
||||||
);
|
);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
logger.finer(() => 'Dispatching flexible push destination to scheduler. '
|
||||||
|
'destination=${destination.name} taskId=$taskId');
|
||||||
final result = switch (destination) {
|
final result = switch (destination) {
|
||||||
PushDestination.nextAvailableSlot =>
|
PushDestination.nextAvailableSlot =>
|
||||||
schedulingEngine.pushFlexibleTaskToNextAvailableSlot(
|
schedulingEngine.pushFlexibleTaskToNextAvailableSlot(
|
||||||
|
|
@ -168,11 +232,22 @@ class FlexibleTaskActionService {
|
||||||
updatedAt: now,
|
updatedAt: now,
|
||||||
),
|
),
|
||||||
};
|
};
|
||||||
|
logger.debug(() => 'Flexible push destination scheduling finished. '
|
||||||
|
'destination=${destination.name} taskId=$taskId '
|
||||||
|
'outcome=${result.outcomeCode.name} changeCount=${result.changes.length} '
|
||||||
|
'noticeCount=${result.notices.length}');
|
||||||
|
if (result.outcomeCode != SchedulingOutcomeCode.success) {
|
||||||
|
logger.warn(() => 'Handled flexible push issue. '
|
||||||
|
'destination=${destination.name} taskId=$taskId '
|
||||||
|
'outcome=${result.outcomeCode.name} notices=${result.notices}');
|
||||||
|
}
|
||||||
|
logger.fine(() => 'Flexible push result details. '
|
||||||
|
'destination=${destination.name} taskId=$taskId '
|
||||||
|
'changes=${result.changes} notices=${result.notices}');
|
||||||
|
logger.finest(() => 'Flexible push destination result dump. '
|
||||||
|
'destination=${destination.name} taskId=$taskId result=$result');
|
||||||
|
|
||||||
return PushDestinationResult(
|
final activities = _activitiesForPushDestination(
|
||||||
destination: destination,
|
|
||||||
schedulingResult: result,
|
|
||||||
activities: _activitiesForPushDestination(
|
|
||||||
destination: destination,
|
destination: destination,
|
||||||
input: input,
|
input: input,
|
||||||
result: result,
|
result: result,
|
||||||
|
|
@ -180,7 +255,15 @@ class FlexibleTaskActionService {
|
||||||
operationId: opId,
|
operationId: opId,
|
||||||
occurredAt: now,
|
occurredAt: now,
|
||||||
existingActivities: existingActivities,
|
existingActivities: existingActivities,
|
||||||
),
|
);
|
||||||
|
logger.debug(() => 'Flexible push destination activities prepared. '
|
||||||
|
'destination=${destination.name} taskId=$taskId '
|
||||||
|
'activityCount=${activities.length}');
|
||||||
|
|
||||||
|
return PushDestinationResult(
|
||||||
|
destination: destination,
|
||||||
|
schedulingResult: result,
|
||||||
|
activities: activities,
|
||||||
);
|
);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|
@ -193,8 +276,15 @@ class FlexibleTaskActionService {
|
||||||
required String taskId,
|
required String taskId,
|
||||||
DateTime? updatedAt,
|
DateTime? updatedAt,
|
||||||
}) {
|
}) {
|
||||||
|
logger.debug(() => 'Moving flexible task to backlog from push destination. '
|
||||||
|
'taskId=$taskId taskCount=${input.tasks.length} '
|
||||||
|
'hasExplicitUpdatedAt=${updatedAt != null}');
|
||||||
|
logger.finest(() => 'Move-to-backlog input dump. '
|
||||||
|
'taskId=$taskId tasks=${input.tasks}');
|
||||||
final task = _taskById(input.tasks, taskId);
|
final task = _taskById(input.tasks, taskId);
|
||||||
if (task == null) {
|
if (task == null) {
|
||||||
|
logger.warn(() => 'Handled move-to-backlog issue: task not found. '
|
||||||
|
'taskId=$taskId');
|
||||||
return SchedulingResult(
|
return SchedulingResult(
|
||||||
tasks: input.tasks,
|
tasks: input.tasks,
|
||||||
operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog,
|
operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog,
|
||||||
|
|
@ -211,6 +301,9 @@ class FlexibleTaskActionService {
|
||||||
}
|
}
|
||||||
|
|
||||||
if (!task.isFlexible || task.status != TaskStatus.planned) {
|
if (!task.isFlexible || task.status != TaskStatus.planned) {
|
||||||
|
logger.warn(() => 'Handled move-to-backlog issue: invalid task state. '
|
||||||
|
'taskId=${task.id} taskType=${task.type.name} '
|
||||||
|
'taskStatus=${task.status.name}');
|
||||||
return SchedulingResult(
|
return SchedulingResult(
|
||||||
tasks: input.tasks,
|
tasks: input.tasks,
|
||||||
operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog,
|
operationCode: SchedulingOperationCode.moveFlexibleTaskToBacklog,
|
||||||
|
|
@ -230,6 +323,10 @@ class FlexibleTaskActionService {
|
||||||
task,
|
task,
|
||||||
updatedAt: updatedAt,
|
updatedAt: updatedAt,
|
||||||
);
|
);
|
||||||
|
logger.debug(() => 'Flexible task moved to backlog. '
|
||||||
|
'taskId=${task.id} previousStart=${task.scheduledStart?.toIso8601String()} '
|
||||||
|
'previousEnd=${task.scheduledEnd?.toIso8601String()} '
|
||||||
|
'updatedAt=${updatedAt?.toIso8601String()}');
|
||||||
|
|
||||||
return SchedulingResult(
|
return SchedulingResult(
|
||||||
tasks: List<Task>.unmodifiable(
|
tasks: List<Task>.unmodifiable(
|
||||||
|
|
|
||||||
118
packages/scheduler_core/test/focus_flow_logger_test.dart
Normal file
118
packages/scheduler_core/test/focus_flow_logger_test.dart
Normal 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',
|
||||||
|
);
|
||||||
|
});
|
||||||
|
});
|
||||||
|
}
|
||||||
Loading…
Reference in a new issue