424 lines
15 KiB
Dart
424 lines
15 KiB
Dart
// Batch A (A1/A2) permanent regression suite: FieldTestLogger persistence
|
|
// ownership and durability.
|
|
//
|
|
// Locks the invariant that every event accepted into FieldTestLogger is either
|
|
// durably persisted EXACTLY ONCE, or retained in memory in original chronological
|
|
// order for retry. A pre-commit persistence failure must never silently discard
|
|
// an event, and a post-commit bookkeeping failure must never requeue durable
|
|
// events. Also locks async containment of the periodic timer and dispose() flush,
|
|
// and the runtimeType-only diagnostic (no exception-message disclosure).
|
|
import 'dart:async';
|
|
|
|
import 'package:flutter/foundation.dart';
|
|
import 'package:flutter_test/flutter_test.dart';
|
|
import 'package:drift/native.dart';
|
|
import 'package:drift/drift.dart' as drift;
|
|
import 'package:motorcycle_dash/database/database.dart'
|
|
hide FieldTestEvent, FieldTestSummary, TelemetrySample;
|
|
import 'package:motorcycle_dash/database/database.dart' as dbgen
|
|
show FieldTestEvent;
|
|
import 'package:motorcycle_dash/models/field_test_event.dart';
|
|
import 'package:motorcycle_dash/services/field_test/field_test_logger.dart';
|
|
|
|
typedef EventRow = dbgen.FieldTestEvent;
|
|
|
|
/// Counts every `batch` call and can park or fail it deterministically, so a flush
|
|
/// can be held exactly at its durability commit point without a sleep-only race.
|
|
class _BatchAAppDatabase extends AppDatabase {
|
|
_BatchAAppDatabase() : super.forTesting(NativeDatabase.memory());
|
|
|
|
int batchInvocations = 0;
|
|
bool gateBatch = false;
|
|
final List<Completer<void>> batchGates = [];
|
|
int batchFailuresRemaining = 0;
|
|
|
|
@override
|
|
Future<void> batch(
|
|
FutureOr<void> Function(drift.Batch batch) runInBatch) async {
|
|
batchInvocations++;
|
|
if (gateBatch) {
|
|
final gate = Completer<void>();
|
|
batchGates.add(gate);
|
|
await gate.future;
|
|
}
|
|
if (batchFailuresRemaining > 0) {
|
|
batchFailuresRemaining--;
|
|
throw StateError('BatchA simulated pre-commit persistence failure');
|
|
}
|
|
return super.batch(runInBatch);
|
|
}
|
|
}
|
|
|
|
void main() {
|
|
TestWidgetsFlutterBinding.ensureInitialized();
|
|
|
|
/// The production logger flush timer is a real 3-second Timer.periodic.
|
|
const tickWait = Duration(milliseconds: 3300);
|
|
|
|
late _BatchAAppDatabase db;
|
|
late FieldTestLogger logger;
|
|
var seq = 0;
|
|
|
|
/// Captures debugPrint output so the bounded diagnostic can be asserted to
|
|
/// contain no exception message. Restored in tearDown.
|
|
final capturedPrints = <String>[];
|
|
late DebugPrintCallback originalDebugPrint;
|
|
|
|
setUp(() async {
|
|
db = _BatchAAppDatabase();
|
|
logger = FieldTestLogger(db);
|
|
seq = 0;
|
|
capturedPrints.clear();
|
|
originalDebugPrint = debugPrint;
|
|
debugPrint = (String? message, {int? wrapWidth}) {
|
|
if (message != null) capturedPrints.add(message);
|
|
};
|
|
});
|
|
|
|
tearDown(() async {
|
|
debugPrint = originalDebugPrint;
|
|
for (final gate in db.batchGates) {
|
|
if (!gate.isCompleted) gate.complete();
|
|
}
|
|
db.batchGates.clear();
|
|
db.gateBatch = false;
|
|
db.batchFailuresRemaining = 0;
|
|
logger.dispose();
|
|
await db.close();
|
|
});
|
|
|
|
/// Enqueues a uniquely identifiable event. Identity lives in the message ONLY
|
|
/// for test accounting; the assertions never treat message text as a diagnostic.
|
|
void logEvent(String tag, {EventSeverity severity = EventSeverity.info}) {
|
|
logger.log(
|
|
eventType: FieldTestEventType.sampleAccepted,
|
|
severity: severity,
|
|
message: 'EVT-$tag-${seq++}',
|
|
rideId: 1,
|
|
timestamp: DateTime(2026, 9, 10, 12).add(Duration(milliseconds: seq * 50)),
|
|
);
|
|
}
|
|
|
|
Future<List<EventRow>> persistedEvents() =>
|
|
(db.select(db.fieldTestEvents)
|
|
..orderBy([(e) => drift.OrderingTerm(expression: e.id)]))
|
|
.get();
|
|
|
|
/// Extracts the ordered identity tags from durable rows.
|
|
List<String> tagsOf(List<EventRow> rows) => rows
|
|
.map((r) => r.message.split('-').skip(1).take(2).join('-'))
|
|
.toList();
|
|
|
|
Map<String, int> tagCounts(List<EventRow> rows) {
|
|
final counts = <String, int>{};
|
|
for (final tag in tagsOf(rows)) {
|
|
counts[tag] = (counts[tag] ?? 0) + 1;
|
|
}
|
|
return counts;
|
|
}
|
|
|
|
List<String> duplicatedTags(List<EventRow> rows) =>
|
|
tagCounts(rows).entries.where((e) => e.value > 1).map((e) => e.key).toList()
|
|
..sort();
|
|
|
|
/// Runs [body] in a guarded zone and returns every uncaught async error, so
|
|
/// timer/dispose Future ownership regressions surface as data, not as an opaque
|
|
/// failure.
|
|
Future<List<Object>> captureUncaught(Future<void> Function() body) async {
|
|
final uncaught = <Object>[];
|
|
await runZonedGuarded(body, (error, stackTrace) => uncaught.add(error));
|
|
return uncaught;
|
|
}
|
|
|
|
group('Batch A: FieldTestLogger durability', () {
|
|
test('F1 a successful flush persists owned events exactly once', () async {
|
|
logEvent('A');
|
|
logEvent('B');
|
|
logEvent('C');
|
|
expect(logger.currentQueueDepth, 3);
|
|
|
|
await logger.flush();
|
|
|
|
final rows = await persistedEvents();
|
|
expect(rows, hasLength(3));
|
|
expect(duplicatedTags(rows), isEmpty);
|
|
expect(logger.currentQueueDepth, 0,
|
|
reason: 'the owned snapshot is removed before the await');
|
|
expect(logger.totalFlushed, 3, reason: 'success-only accounting');
|
|
expect(logger.failedFlushCount, 0);
|
|
expect(db.batchInvocations, 1);
|
|
});
|
|
|
|
test('F2 a pre-commit failure restores the owned snapshot', () async {
|
|
logEvent('A');
|
|
logEvent('B');
|
|
logEvent('C');
|
|
|
|
db.batchFailuresRemaining = 1;
|
|
await logger.flush();
|
|
|
|
expect(await persistedEvents(), isEmpty,
|
|
reason: 'a failed attempt commits nothing');
|
|
expect(logger.currentQueueDepth, 3,
|
|
reason: 'owned events are retained for retry, never discarded');
|
|
expect(logger.failedFlushCount, 1,
|
|
reason: 'existing failure accounting preserved');
|
|
expect(logger.totalFlushed, 0);
|
|
});
|
|
|
|
test('F3 arrivals during a failed flush keep order A B C D E', () async {
|
|
logEvent('A');
|
|
logEvent('B');
|
|
logEvent('C');
|
|
|
|
db.gateBatch = true;
|
|
final pending = logger.flush();
|
|
await pumpEventQueue(times: 20);
|
|
expect(db.batchInvocations, 1, reason: 'flush parked at the commit point');
|
|
|
|
// D and E arrive DURING the await and must end up behind the restored
|
|
// snapshot: A B C D E, never D E A B C.
|
|
logEvent('D');
|
|
logEvent('E');
|
|
|
|
db.batchFailuresRemaining = 1;
|
|
db.gateBatch = false;
|
|
db.batchGates.single.complete();
|
|
await pending;
|
|
|
|
expect(await persistedEvents(), isEmpty);
|
|
expect(logger.currentQueueDepth, 5,
|
|
reason: 'owned A B C restored in front of arrivals D E');
|
|
|
|
// Order is proven behaviourally by the retry's durable row order.
|
|
await logger.flush();
|
|
final rows = await persistedEvents();
|
|
expect(tagsOf(rows), ['A-0', 'B-1', 'C-2', 'D-3', 'E-4'],
|
|
reason: 'chronological order survives restoration and retry');
|
|
expect(duplicatedTags(rows), isEmpty);
|
|
});
|
|
|
|
test('F4 failure then retry yields no duplicates and nothing missing',
|
|
() async {
|
|
for (final tag in ['A', 'B', 'C', 'D']) {
|
|
logEvent(tag);
|
|
}
|
|
|
|
db.batchFailuresRemaining = 1;
|
|
await logger.flush();
|
|
expect(await persistedEvents(), isEmpty);
|
|
expect(logger.currentQueueDepth, 4);
|
|
|
|
await logger.flush();
|
|
final rows = await persistedEvents();
|
|
expect(rows, hasLength(4), reason: 'every event eventually durable');
|
|
expect(duplicatedTags(rows), isEmpty, reason: 'exactly once');
|
|
expect(tagCounts(rows).keys.toList()..sort(), ['A-0', 'B-1', 'C-2', 'D-3'],
|
|
reason: 'nothing missing');
|
|
expect(logger.failedFlushCount, 1);
|
|
expect(logger.totalFlushed, 4);
|
|
});
|
|
|
|
test('F5 arrivals during a successful flush are left for the next flush',
|
|
() async {
|
|
logEvent('A');
|
|
logEvent('B');
|
|
logEvent('C');
|
|
|
|
db.gateBatch = true;
|
|
final pending = logger.flush();
|
|
await pumpEventQueue(times: 20);
|
|
logEvent('D');
|
|
logEvent('E');
|
|
db.gateBatch = false;
|
|
db.batchGates.single.complete();
|
|
await pending;
|
|
|
|
var rows = await persistedEvents();
|
|
expect(tagsOf(rows), ['A-0', 'B-1', 'C-2'],
|
|
reason: 'only the owned snapshot commits');
|
|
expect(logger.currentQueueDepth, 2, reason: 'D E remain buffered');
|
|
|
|
await logger.flush();
|
|
rows = await persistedEvents();
|
|
expect(tagsOf(rows), ['A-0', 'B-1', 'C-2', 'D-3', 'E-4']);
|
|
expect(duplicatedTags(rows), isEmpty, reason: 'exactly once overall');
|
|
expect(db.batchInvocations, 2);
|
|
expect(logger.totalFlushed, 5);
|
|
});
|
|
|
|
test('F6 concurrent flush callers yield exactly one owner per event',
|
|
() async {
|
|
logEvent('A');
|
|
logEvent('B');
|
|
logEvent('C');
|
|
|
|
db.gateBatch = true;
|
|
final first = logger.flush();
|
|
await pumpEventQueue(times: 20);
|
|
expect(db.batchInvocations, 1);
|
|
|
|
// Concurrent callers must not take a second snapshot of the same events.
|
|
final others = [logger.flush(), logger.flush(), logger.flush()];
|
|
await pumpEventQueue(times: 20);
|
|
expect(db.batchInvocations, 1,
|
|
reason: 'the synchronous ownership guard is raised before the await');
|
|
|
|
db.gateBatch = false;
|
|
db.batchGates.single.complete();
|
|
await first;
|
|
await Future.wait(others);
|
|
|
|
final rows = await persistedEvents();
|
|
expect(tagsOf(rows), ['A-0', 'B-1', 'C-2']);
|
|
expect(duplicatedTags(rows), isEmpty);
|
|
expect(db.batchInvocations, 1);
|
|
});
|
|
test('F7 stopSession coordinates safely with an in-flight periodic flush',
|
|
() async {
|
|
logger.startSession(1);
|
|
logEvent('A');
|
|
logEvent('B');
|
|
logEvent('C');
|
|
|
|
db.gateBatch = true;
|
|
final periodic = logger.flush();
|
|
await pumpEventQueue(times: 20);
|
|
expect(db.batchInvocations, 1, reason: 'the periodic owner holds A B C');
|
|
|
|
// Tail arrives while another owner is in flight.
|
|
logEvent('D');
|
|
|
|
db.gateBatch = false;
|
|
final stop = logger.stopSession();
|
|
for (final gate in db.batchGates) {
|
|
if (!gate.isCompleted) gate.complete();
|
|
}
|
|
await periodic;
|
|
await stop;
|
|
|
|
final rows = (await persistedEvents())
|
|
.where((r) => r.message.startsWith('EVT-'))
|
|
.toList();
|
|
expect(tagsOf(rows), ['A-0', 'B-1', 'C-2', 'D-3'],
|
|
reason: 'exactly once each, in chronological order, tail preserved');
|
|
expect(duplicatedTags(rows), isEmpty);
|
|
expect(logger.currentQueueDepth, 0,
|
|
reason: 'stopSession drained the tail it owned');
|
|
});
|
|
|
|
test('F8 failure accounting is preserved across mixed outcomes', () async {
|
|
logEvent('A');
|
|
db.batchFailuresRemaining = 1;
|
|
await logger.flush();
|
|
expect(logger.failedFlushCount, 1);
|
|
expect(logger.totalFlushed, 0, reason: 'success-only accounting');
|
|
|
|
logEvent('B');
|
|
await logger.flush();
|
|
expect(logger.failedFlushCount, 1, reason: 'no additional failure');
|
|
expect(logger.totalFlushed, 2, reason: 'A retried plus B');
|
|
expect(await persistedEvents(), hasLength(2));
|
|
});
|
|
|
|
test('F9 the failure diagnostic discloses no exception message', () async {
|
|
logEvent('A');
|
|
db.batchFailuresRemaining = 1;
|
|
await logger.flush();
|
|
|
|
final diagnostics =
|
|
capturedPrints.where((m) => m.contains('[FieldTestLogger]')).toList();
|
|
expect(diagnostics, isNotEmpty, reason: 'a bounded diagnostic is emitted');
|
|
for (final message in diagnostics) {
|
|
expect(message, contains('class=StateError'),
|
|
reason: 'runtimeType only, per the MotorSignal precedent');
|
|
expect(message, contains('events=1'), reason: 'bounded event count');
|
|
expect(message, isNot(contains('simulated')),
|
|
reason: 'the exception message must never be disclosed');
|
|
expect(message, isNot(contains('BatchA')),
|
|
reason: 'no exception text or payload detail');
|
|
}
|
|
});
|
|
|
|
test('F10 post-commit bookkeeping cannot requeue durable events', () async {
|
|
logEvent('A');
|
|
logEvent('B');
|
|
await logger.flush();
|
|
|
|
expect(await persistedEvents(), hasLength(2));
|
|
expect(logger.currentQueueDepth, 0);
|
|
expect(logger.failedFlushCount, 0,
|
|
reason: 'nothing after the commit point is a persistence failure');
|
|
expect(logger.totalFlushed, 2);
|
|
|
|
// Restoration lives only in the pre-commit catch, so no later pass may
|
|
// re-write events that are already durable.
|
|
await logger.flush();
|
|
await logger.flush();
|
|
expect(await persistedEvents(), hasLength(2), reason: 'never duplicated');
|
|
expect(db.batchInvocations, 1, reason: 'an empty buffer is a no-op');
|
|
});
|
|
|
|
test('F11 an empty flush is a no-op', () async {
|
|
await logger.flush();
|
|
expect(db.batchInvocations, 0);
|
|
expect(logger.totalFlushed, 0);
|
|
expect(logger.failedFlushCount, 0);
|
|
expect(logger.currentQueueDepth, 0);
|
|
});
|
|
|
|
test('F12 a sub-interval stopSession persists its tail before returning',
|
|
() async {
|
|
logger.startSession(1);
|
|
logEvent('A');
|
|
logEvent('B');
|
|
expect(db.batchInvocations, 0, reason: 'no periodic tick has run yet');
|
|
|
|
await logger.stopSession();
|
|
|
|
final rows = (await persistedEvents())
|
|
.where((r) => r.message.startsWith('EVT-'))
|
|
.toList();
|
|
expect(tagsOf(rows), ['A-0', 'B-1'],
|
|
reason: 'the tail is durable before stopSession returned');
|
|
expect(logger.currentQueueDepth, 0);
|
|
});
|
|
|
|
test('F13 timer and dispose flush failures raise no uncaught error',
|
|
() async {
|
|
final uncaught = await captureUncaught(() async {
|
|
// Periodic-timer path: a real failure inside a timer-owned flush.
|
|
logEvent('A');
|
|
db.batchFailuresRemaining = 1;
|
|
await Future<void>.delayed(tickWait);
|
|
await pumpEventQueue(times: 40);
|
|
|
|
// dispose() path: an unawaited, explicitly owned flush that fails.
|
|
final localLogger = FieldTestLogger(db);
|
|
localLogger.log(
|
|
eventType: FieldTestEventType.sampleAccepted,
|
|
severity: EventSeverity.info,
|
|
message: 'EVT-DISPOSE-0',
|
|
rideId: 1,
|
|
);
|
|
db.batchFailuresRemaining = 1;
|
|
localLogger.dispose();
|
|
await pumpEventQueue(times: 40);
|
|
});
|
|
|
|
expect(uncaught, isEmpty,
|
|
reason: 'both the timer and dispose flush Futures must be explicitly '
|
|
'owned so no rejection reaches the zone: $uncaught');
|
|
// A pre-commit failure during dispose retains rather than discards, and
|
|
// commits nothing.
|
|
expect(
|
|
(await persistedEvents())
|
|
.where((r) => r.message.startsWith('EVT-'))
|
|
.toList(),
|
|
isEmpty,
|
|
reason: 'failed attempts commit nothing');
|
|
expect(logger.failedFlushCount, greaterThanOrEqualTo(1));
|
|
});
|
|
});
|
|
}
|