feat(log): crash-survivable FileLogSink + dev/prod verbosity toggle (T-432)

First increment of the observability epic (T-425), the productive pivot after
the ConPTY freeze refused to reproduce on CI: if we can't reproduce it, make
the next occurrence leave evidence.

- FileLogSink (lib/kernel/src/file_log_sink.dart): synchronous, crash-survivable
  LogSink. Appends each record as one JSON line to a size-rotated file; fsyncs
  warn/error + risky-source (pty/ffi/conpty/watchdog) records immediately so the
  last breadcrumb is on disk before a hard death, batches the rest on a timer.
  Never throws. Flutter-free → unit-tested under dart test against a temp dir.
- logDirectory() (paths.dart): persistent per-platform log dir (LOCALAPPDATA /
  ~/Library/Logs / $XDG_STATE_HOME) — durable across reboot, unlike the
  ephemeral socketDirectory.
- resolveLogLevel() (log.dart): the requested dev/prod toggle. CLIDE_LOG
  dart-define → CLIDE_LOG env → app.log.level setting → warn(release)/info(debug).
  Lenient parse; an invalid source falls through.
- Boot wiring (facade.boot + main.dart): FileLogSink leads the sink chain (so a
  crash records before the volatile stderr/ring sinks) and the resolved level
  sets Logger.minLevel.

Tests: FileLogSink (JSON shape, error/stack, rotation cap, append-across-restart,
timer-cancel), resolveLogLevel precedence + fall-through, logDirectory per-OS.
Coverage gate 95.11%.

Follow-ups under T-425: live toggle CLI/command/chip (T-433), FFI breadcrumbs
(T-434), watchdog isolate (T-435), CI artifact wiring (T-436).

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
2026-06-15 09:29:41 +02:00
co-authored by Claude Opus 4.8
parent b3acb8a34c
commit 85cc34e09c
12 changed files with 494 additions and 2 deletions
+108
View File
@@ -0,0 +1,108 @@
import 'dart:convert';
import 'dart:io';
import 'package:clide/kernel/kernel.dart';
import 'package:flutter_test/flutter_test.dart';
LogRecord _rec(LogLevel level, String src, String msg, {Object? error, StackTrace? stack}) =>
LogRecord(level: level, source: src, message: msg, timestamp: DateTime.utc(2026, 6, 15, 12), error: error, stackTrace: stack);
void main() {
late Directory dir;
setUp(() => dir = Directory.systemTemp.createTempSync('clide-filelog-'));
tearDown(() {
if (dir.existsSync()) dir.deleteSync(recursive: true);
});
File active() => File('${dir.path}${Platform.pathSeparator}clide.log');
File archive(int i) => File('${dir.path}${Platform.pathSeparator}clide.$i.log');
group('FileLogSink', () {
test('appends one JSON line per record with the expected shape', () async {
final sink = FileLogSink(dir: dir, startFlushTimer: false);
sink(_rec(LogLevel.info, 'boot', 'hello'));
sink(_rec(LogLevel.warn, 'pty', 'spawned', error: 'note'));
await sink.close();
final lines = active().readAsLinesSync();
expect(lines, hasLength(2));
final a = jsonDecode(lines[0]) as Map<String, Object?>;
expect(a['lvl'], 'info');
expect(a['src'], 'boot');
expect(a['msg'], 'hello');
expect(a['ts'], '2026-06-15T12:00:00.000Z');
expect(a.containsKey('err'), isFalse);
final b = jsonDecode(lines[1]) as Map<String, Object?>;
expect(b['lvl'], 'warn');
expect(b['err'], 'note');
});
test('encodes error + stack trace fields when present', () async {
final sink = FileLogSink(dir: dir, startFlushTimer: false);
final st = StackTrace.current;
sink(_rec(LogLevel.error, 'ffi', 'boom', error: 'EBADF', stack: st));
await sink.close();
final rec = jsonDecode(active().readAsLinesSync().single) as Map<String, Object?>;
expect(rec['err'], 'EBADF');
expect(rec['stack'], st.toString());
});
test('creates the log directory if it does not exist', () async {
final nested = Directory('${dir.path}${Platform.pathSeparator}a${Platform.pathSeparator}b');
final sink = FileLogSink(dir: nested, startFlushTimer: false);
sink(_rec(LogLevel.info, 's', 'm'));
await sink.close();
expect(File('${nested.path}${Platform.pathSeparator}clide.log').existsSync(), isTrue);
});
test('rotates past maxBytes and caps archives at maxFiles', () async {
// ~80-byte lines, 100-byte cap → a rotation every couple of records.
final sink = FileLogSink(dir: dir, maxBytes: 100, maxFiles: 2, startFlushTimer: false);
for (var i = 0; i < 6; i++) {
sink(_rec(LogLevel.info, 's', 'msg$i'));
}
await sink.close();
expect(active().existsSync(), isTrue);
expect(archive(1).existsSync(), isTrue);
// maxFiles=2 keeps active + .1 only — .2 must never appear.
expect(archive(2).existsSync(), isFalse);
// The newest record is in the active file.
expect(active().readAsStringSync(), contains('msg5'));
});
test('append mode preserves an existing log across sink restarts', () async {
final first = FileLogSink(dir: dir, startFlushTimer: false);
first(_rec(LogLevel.info, 's', 'before'));
await first.close();
final second = FileLogSink(dir: dir, startFlushTimer: false);
second(_rec(LogLevel.info, 's', 'after'));
await second.close();
final lines = active().readAsLinesSync();
expect(lines, hasLength(2));
expect((jsonDecode(lines[0]) as Map)['msg'], 'before');
expect((jsonDecode(lines[1]) as Map)['msg'], 'after');
});
test('close cancels the flush timer cleanly (no pending-timer leak)', () async {
final sink = FileLogSink(dir: dir, flushInterval: const Duration(milliseconds: 10));
sink(_rec(LogLevel.info, 's', 'm'));
await sink.close();
// Reaching here without the test runner flagging a pending timer is the
// assertion; also confirm a post-close write is a no-op, not a throw.
sink(_rec(LogLevel.info, 's', 'after-close'));
expect(active().readAsLinesSync(), hasLength(1));
});
test('activePath points at the live file', () {
final sink = FileLogSink(dir: dir, startFlushTimer: false);
expect(sink.activePath, active().path);
});
});
}
+42
View File
@@ -75,4 +75,46 @@ void main() {
expect(got, isEmpty);
});
});
group('parseLogLevel', () {
test('parses each level name case-insensitively, trimmed', () {
for (final l in LogLevel.values) {
expect(parseLogLevel(l.name), l);
expect(parseLogLevel(l.name.toUpperCase()), l);
expect(parseLogLevel(' ${l.name} '), l);
}
});
test('null / blank / unknown → null', () {
expect(parseLogLevel(null), isNull);
expect(parseLogLevel(''), isNull);
expect(parseLogLevel(' '), isNull);
expect(parseLogLevel('verbose'), isNull);
});
});
group('resolveLogLevel (dev/prod verbosity toggle)', () {
test('build-mode default when no source is set: warn release / info debug', () {
expect(resolveLogLevel(isRelease: true), LogLevel.warn);
expect(resolveLogLevel(isRelease: false), LogLevel.info);
});
test('precedence: dartDefine > env > setting > default', () {
// setting only
expect(resolveLogLevel(isRelease: true, settingValue: 'debug'), LogLevel.debug);
// env beats setting
expect(resolveLogLevel(isRelease: true, envVar: 'error', settingValue: 'debug'), LogLevel.error);
// dartDefine beats both
expect(resolveLogLevel(isRelease: false, dartDefine: 'trace', envVar: 'error', settingValue: 'debug'), LogLevel.trace);
});
test('an unknown/blank higher source falls through to the next', () {
// empty dart-define (the String.fromEnvironment default) is skipped
expect(resolveLogLevel(isRelease: true, dartDefine: '', envVar: 'info'), LogLevel.info);
// garbage env falls through to the setting
expect(resolveLogLevel(isRelease: true, envVar: 'loud', settingValue: 'warn'), LogLevel.warn);
// all invalid → build-mode default
expect(resolveLogLevel(isRelease: false, dartDefine: 'x', envVar: 'y', settingValue: 'z'), LogLevel.info);
});
});
}