From 9a7f8933c7f2bfc336ce0f08f1124225c211c06c Mon Sep 17 00:00:00 2001 From: Ashley Venn Date: Thu, 2 Jul 2026 18:38:41 -0700 Subject: [PATCH] feat: expand runtime logger levels --- apps/focus_flow_flutter/README.md | 18 ++- .../app/runtime/focus_flow_file_logger.dart | 93 ++++++++++-- .../runtime/focus_flow_runtime_config.dart | 15 +- .../test/app/runtime_config_test.dart | 139 +++++++++++++++++- 4 files changed, 243 insertions(+), 22 deletions(-) diff --git a/apps/focus_flow_flutter/README.md b/apps/focus_flow_flutter/README.md index a4676a1..cacbb15 100644 --- a/apps/focus_flow_flutter/README.md +++ b/apps/focus_flow_flutter/README.md @@ -51,16 +51,30 @@ Supported optional keys: ```json { - "LogLevel": "debug", + "LogLevel": "fine", "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 `focus_flow.log` inside it. If either key is absent or invalid, file logging is 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 Allowed app imports include public scheduler APIs such as: diff --git a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart index dd63d15..74e2b1c 100644 --- a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart +++ b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_file_logger.dart @@ -8,6 +8,9 @@ import 'dart:io'; import 'focus_flow_runtime_config.dart'; +/// Lazily creates a log message only after the target level is enabled. +typedef FocusFlowLogMessage = Object? Function(); + /// Minimal append-only file logger for FocusFlow runtime diagnostics. final class FocusFlowFileLogger { /// Creates a logger with explicit runtime state. @@ -63,23 +66,33 @@ final class FocusFlowFileLogger { /// Whether this logger currently writes to a file. bool get isEnabled => minimumLevel != null && logFilePath != null; - /// Writes a trace-level [message] when enabled for trace. - Future trace(String message) { - return write(FocusFlowLogLevel.trace, message); + /// Writes a finest-level [message] when enabled for finest logging. + Future finest(Object? message) { + return write(FocusFlowLogLevel.finest, message); + } + + /// Writes a finer-level [message] when enabled for finer logging. + Future finer(Object? message) { + return write(FocusFlowLogLevel.finer, message); + } + + /// Writes a fine-level [message] when enabled for fine logging. + Future fine(Object? message) { + return write(FocusFlowLogLevel.fine, message); } /// Writes a debug-level [message] when enabled for debug or lower. - Future debug(String message) { + Future debug(Object? message) { return write(FocusFlowLogLevel.debug, message); } /// Writes an info-level [message] when enabled for info or lower. - Future info(String message) { + Future info(Object? message) { return write(FocusFlowLogLevel.info, message); } /// Writes a warning-level [message] when enabled for warning or lower. - Future warn(String message, {Object? error, StackTrace? stackTrace}) { + Future warn(Object? message, {Object? error, StackTrace? stackTrace}) { return write( FocusFlowLogLevel.warn, message, @@ -89,7 +102,7 @@ final class FocusFlowFileLogger { } /// Writes an error-level [message] when file logging is enabled. - Future error(String message, {Object? error, StackTrace? stackTrace}) { + Future error(Object? message, {Object? error, StackTrace? stackTrace}) { return write( FocusFlowLogLevel.error, message, @@ -101,7 +114,7 @@ final class FocusFlowFileLogger { /// Writes [message] at [level] when it passes the configured threshold. Future write( FocusFlowLogLevel level, - String message, { + Object? message, { Object? error, StackTrace? stackTrace, }) async { @@ -113,12 +126,23 @@ final class FocusFlowFileLogger { return; } + 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(' ') - ..write(message.trim()); + ..write(' '); + if (caller != null) { + buffer + ..write('caller=') + ..write(caller) + ..write(' '); + } + buffer.write(resolvedMessage); if (error != null) { buffer ..write(' | error=') @@ -145,17 +169,56 @@ bool _shouldWrite(FocusFlowLogLevel level, FocusFlowLogLevel 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, + 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'); +} + /// Joins [base] and [child] with the platform path separator. String _joinPath(String base, String child) { if (base.endsWith('/') || base.endsWith(r'\')) { diff --git a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart index 1d68d35..0013ea8 100644 --- a/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart +++ b/apps/focus_flow_flutter/lib/app/runtime/focus_flow_runtime_config.dart @@ -67,10 +67,16 @@ final class FocusFlowRuntimeConfig { bool get enablesFileLogging => logLevel != null && logFileLocation != null; } -/// Supported FocusFlow file logging levels. +/// Supported FocusFlow file logging levels, ordered from most to least verbose. enum FocusFlowLogLevel { - /// Logs every message, including trace-level detail. - trace, + /// 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, @@ -90,6 +96,9 @@ enum FocusFlowLogLevel { if (normalized == null || normalized.isEmpty) { return null; } + if (normalized == 'trace') { + return finest; + } for (final level in FocusFlowLogLevel.values) { if (level.name == normalized) { return level; diff --git a/apps/focus_flow_flutter/test/app/runtime_config_test.dart b/apps/focus_flow_flutter/test/app/runtime_config_test.dart index e9a38cf..7cc5251 100644 --- a/apps/focus_flow_flutter/test/app/runtime_config_test.dart +++ b/apps/focus_flow_flutter/test/app/runtime_config_test.dart @@ -38,16 +38,26 @@ void main() { '${directory.path}${Platform.pathSeparator}config.json', ); await configFile.writeAsString( - jsonEncode({'LogLevel': 'trace', 'LogfileLocation': directory.path}), + jsonEncode({'LogLevel': 'finest', 'LogfileLocation': directory.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.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', () { final config = FocusFlowRuntimeConfig.fromJson({ 'LogLevel': 'debug', @@ -107,5 +117,130 @@ void main() { expect(contents, contains('written warning')); 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'))); + }); }); }