Query does not complete if the database is created outside WidgetTester.runAsync

[Mike278]

Sorry Simon, I've got another one! These tests pass with moor 3.4.0 and flutter 1.20.4, but tests 3 and 4 do not complete with moor 4.3.2 and flutter 2.2.1. I know in general you're supposed to mock or avoid async in widget tests, so this may be a case of "that should have never worked", but it'd at least be good to understand what's going on here.

import 'dart:async';

import 'package:flutter_test/flutter_test.dart';
import 'package:moor/ffi.dart';
import 'package:moor/moor.dart';

class TestDb extends GeneratedDatabase {
  TestDb() : super(SqlTypeSystem.withDefaults(), VmDatabase.memory());
  @override
  final List<TableInfo> allTables = const [];
  @override
  final int schemaVersion = 1;
}

Future<int> selectOne(TestDb _db) => _db
    .customSelect('select 1 a')
    .map((row) => row.read<int>('a'))
    .getSingle();

void main() {
  moorRuntimeOptions.dontWarnAboutMultipleDatabases = true;

  testWidgets('1', (tester) async {
    final db = TestDb();
    expect(await selectOne(db), 1); // completes
  });

  testWidgets('2', (tester) async {
    await tester.runAsync(() async {
      final db = TestDb();
      expect(await selectOne(db), 1); // completes
    });
  });

  testWidgets('3', (tester) async {
    final db = TestDb();
    await tester.runAsync(() async {
      expect(await selectOne(db), 1);  // does not complete
    });
  });

  testWidgets('4', (tester) async {
    final db = await tester.runAsync(() async {
      return TestDb();
    });
    expect(await selectOne(db), 1); // does not complete
  });
}

[simolus3]

Sorry, I tried to investigate what's going wrong here but I'm pretty much clueless.

I think it has something to do with the custom zones used by Flutters test library. I've added some print statements to the moor's mutex where the deadlock is appearently coming from (I already don't like where this is going):

diff --git a/moor/lib/src/utils/synchronized.dart b/moor/lib/src/utils/synchronized.dart
index aebe8b6b..bd6a62bf 100644
--- a/moor/lib/src/utils/synchronized.dart
+++ b/moor/lib/src/utils/synchronized.dart
@@ -7,22 +7,29 @@ class Lock {
   /// Waits for previous [synchronized]-calls on this [Lock] to complete, and
   /// then calls [block] before further [synchronized] calls are allowed.
   Future<T> synchronized<T>(FutureOr<T> Function() block) {
+    print('synchronized called');
     final previous = _last;
     // This controller may not be sync: It must complete just after
     // callBlockAndComplete completes.
     final blockCompleted = Completer<void>();
-    _last = blockCompleted.future;
+    _last = blockCompleted.future..whenComplete(() => print('whenComplete'));
 
     // Note: We can't use async/await here because this future must complete
     // just before the blockCompleted completer.
     Future<T> callBlockAndComplete() async {
+      print('starting an operation');
       try {
         return await block();
       } finally {
+        print('done with operation');
         blockCompleted.complete();
       }
     }
 
-    return previous.then((_) => callBlockAndComplete());
+    print('attaching listener');
+    return previous.then((_) {
+      print('previous done');
+      return callBlockAndComplete();
+    });
   }
 }

For test 2, this prints

synchronized called
attaching listener
previous done
starting an operation
done with operation
synchronized called
attaching listener
whenComplete
previous done
starting an operation
Moor: Sent select 1 a with args []
done with operation
whenComplete

For test 3, it prints:

synchronized called
attaching listener
previous done
starting an operation
done with operation
synchronized called
attaching listener
whenComplete

Now, I really have no idea how the completer can complete (as evidenced by whenComplete being printed) with a listener being present (print just before the then) without resuming the callback in future.then. There's something weird here, but as far as I can tell it's not coming from moor.

[Mike278]

Very bizarre... to make matters even more confusing, test 4 prints:

synchronized called
attaching listener
previous done
starting an operation

My understanding is that WidgetTester.runAsync is for running "real" async work outside the fake async zone. I kinda expected 1 and 4 to always fail because await is outside runAsync, so I don't understand why 1 passes or why 3 fails - it seems like it's sensitive to the zone where the database is created. Interesting that it works just running against the lock:

import 'dart:async';

import 'package:flutter_test/flutter_test.dart';
import 'package:moor/ffi.dart';
import 'package:moor/moor.dart';
import 'package:moor/src/utils/synchronized.dart';

class TestDb extends GeneratedDatabase {
  TestDb() : super(SqlTypeSystem.withDefaults(), VmDatabase.memory());
  @override
  final List<TableInfo> allTables = const [];
  @override
  final int schemaVersion = 1;
}

Future<int> selectOne(TestDb _db) => _db
    .customSelect('select 1 a')
    .map((row) => row.read<int>('a'))
    .getSingle();

Future<int> returnOne(Lock _lock) => _lock.synchronized(() {
  return Future.value(1);
});

Future<int> returnOneDelayed(Lock _lock) => _lock.synchronized(() {
  return Future.delayed(Duration(milliseconds: 100), () => 1);
});

void main() {

  testWidgets('lock', (tester) async {
    final lock = Lock();
    await tester.runAsync(() async {
      expect(await returnOne(lock), 1);
    });
  });

  testWidgets('lock+delay', (tester) async {
    final lock = Lock();
    await tester.runAsync(() async {
      expect(await returnOneDelayed(lock), 1);
    });
  });

  testWidgets('db', (tester) async {
    final db = TestDb();
    await tester.runAsync(() async {
      expect(await selectOne(db), 1); // does not complete
    });
  });
}

There aren't any transactions involved, but could using Zone.root in the ZoneSpecification here be causing issues with this in any way? It doesn't seem like either of those have changed significantly though, hmmm...

[simolus3]

The engine zone used for the migration callback does go through actually. I thought that maybe it would help to wrap everything in a transaction because it uses a similar mechanism, but that didn't fix anything.

[lsaudon]

I have the same issue.

[Mike278]

Possibly related? dart-lang/sdk#40131

[simolus3]

Interesting, but the zone in runAsync delegates scheduling microtasks to the root zone so that shouldn't be an issue.

I tried using blockCompleted.complete(Future.value()); instead of blockCompleted.complete to avoid an implicit _nullFuture, but that doesn't help.

[Mike278]

Thanks for your help with this, I appreciate you taking the time to try and figure out what's going on.

The rationale for runAsync/fake_async seems to be making widget tests deterministic and avoiding flakiness. But the combo of zones+async is a "thorny, almost entirely undocumented, hot mess" according to dart-lang/sdk#40131... so probably not a great language feature to design a flakiness-avoiding library around!

I think I'm ready to give up fighting the constraints of widget tests. The return just isn't worth it, and the widget test framework seems determined to fulfil the prophecy that async == flaky. flutter/flutter#60136 is an excellent example. The author's comments (1, 2) perfectly capture my experience here, but that PR was reduced to a documentation change, and the exact problem the author was trying to address still occurs even when following that documentation (i.e. Expose a [Future] in your application code that signals the readiness of your widget tree, then await that future inside [callback]., as this simple repro does).

So I guess I have to follow the other suggestion: Consider restructuring your code so you do not need [runAsync].

I think the problem is that I'm trying to write highly integrated widget tests, while clearly they're optimized for a much narrower use case.

This is a shame because widget tests are much less useful if you're forced to reduce them to "tap button, assert the data from my mocked callback is now displayed". This means you now also have to write an equivalent non-widget unit test for the "bloc/viewcontroller/viewmodel" layer (i.e. call onButtonTap, assert some stream emits a new value). And also cover the gap with integration tests using flutter_driver, which requires the emulator so it'll definitely introduce flakiness (the irony!). And this is all to protect myself from writing writing a test that could be flaky.

I understand its generally a good idea to separate out different types of tests like this (and you should definitely still write detailed tests of specific components in isolation), but I've found writing highly integrated widget tests gets the most bang for your buck while iterating quickly.

Anyway sorry for the rant and thanks again for the help debugging, gonna close this out since there's nothing moor to do here.

[kuhnroyal]

I am now running into the same issue trying to migrate to Flutter 2.0.0 :(
This has worked up until now. It would be interesting to find out which Dart/Flutter change caused this somewhere between 1.22.6 and 2.0.0.

I mean I am all for splitting the UI layer from the database but there something called legacy code...

[simolus3]

Hm, I didn't find any relevant diffs in the flutter_test package from 2.0.6 to 2.2.0. I'm wondering if this is a very obscure bug in the dart:async implementation that we're hitting (or worse, a Dart VM bug).

[kuhnroyal]

Hm, I didn't find any relevant diffs in the flutter_test package from 2.0.6 to 2.2.0. I'm wondering if this is a very obscure bug in the dart:async implementation that we're hitting (or worse, a Dart VM bug).

Yea I was wrong, the problem is between 1.22.6 and 2.0.0 - updated my previous comment

[kuhnroyal]

The last version that I can successfully test is 1.25.0-4.0.pre - after that my dependency conflicts are getting too wild.

[kuhnroyal]

This may have been caused by moor.
The test from the issue above runs with flutter: 2.0.6 and moor: 4.0.0-nullsafety.1 but not with moor: 4.1.0.

[kuhnroyal]

https://github.com/simolus3/moor/compare/c5cbd1b..9bb2a24

[kuhnroyal]

Seems the database open handling changed between these version to support Web/Remote DB.

[Mike278]

Just to clarify, the test in the OP includes all the permutations for completeness, but I'm not sure if we should expect 1 and 4 to pass because the await for real async work is outside runAsync.

I expected 3 to pass though - that's the real case we're hitting in practice (i.e. db is created in setUp and used later in a test inside runAsync).

I haven't revisited this yet, but I remember I was able to make some of our broken tests pass by randomly duplicating some await tester.runAsync(tester.pumpAndSettle); lines (I think that was around the point I gave up :D)

Based off the description of flutter/flutter#60136:

Widget tester supports runAsync operation which runs the callback in a real async zone. Today, this simply awaits for the callback. Much like we do for FakeAsync, we should keep track of microtasks and Timers and expose and API to resolve them prior to exiting the real async zone. This is not a silver bullet solution. If apps/tests rely on long running async operations (such as file io, image processing, timers etc), it is highly likely that runAsync() will complete before all "side effects" are achieved.

It feels like the new version of moor takes n microtasks to setup the database, but the flutter test framework happens to run only n-1 microtasks.

[simolus3]

The weird thing about test 3 failing is that the database should be opened inside the runAsync callback. Just creating a database instance does not actually open it, and it shouldn't schedule any microtasks or other things that may interfere with runAsync. So I don't fully understand how changes to the opening logic could have an impact here. I'll try to investigate this further, maybe I overlooked something.

[simolus3]

In hindsight, it's all obvious. We create a Future.value() when the lock is initialized, which happens when the database instance is being created. A Future.value still completes asynchronously, so it implicitly starts a microtask.

All four tests from Mike's example pass with 1068c49. Could you check whether that also happens in more complex scenarios? You can use this function to spot misuse in places where you wouldn't expect async operations: https://github.com/simolus3/moor/blob/1068c4934d85474a0c136b21aa8a42796103809e/moor/test/integration_tests/regress_1235_test.dart#L17-L32

I feel a bit stupid now, but that was impossibly hard to debug :D

[Mike278]

Weird! I wrote the test in #1235 (comment) because that's what I thought the issue was, but 'lock' and 'lock+delay' both pass so I figured it was something else. Either way, definitely super finicky and hard to debug - nice catch! I'll definitely give this a try tomorrow. Is there any way you could put this on a branch from master so it's easier to put it through ci?

[kuhnroyal]

This still hangs and this is how I have built a lot of legacy tests :/

  group('complex', () {
    TestDb db;

    setUp(() {
      db = TestDb();
    });

    tearDown(() async {
      await db.close();
    });

    testWidgets('1', (tester) async {
      expect(await selectOne(db), 1);
    });
  });

[Mike278]

Is it actually hanging at selectOne? IIRC I’ve had some issues with db.close in tearDown. Either way, the fact that real async work was ever able to complete outside runAsync was probably “luck”, so you might have to bite the bullet and wrap those calls in runAsync.

…

On Jun 9, 2021, at 6:13 AM, Peter Leibiger ***@***.***> wrote:  This still hangs and this is how I have built a lot of legacy tests :/ group('complex', () { TestDb db; setUp(() { db = TestDb(); }); tearDown(() async { await db.close(); }); testWidgets('1', (tester) async { expect(await selectOne(db), 1); }); }); — You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub, or unsubscribe.

[kuhnroyal]

You are correct, it hangs on the await db.close() call

[simolus3]

Actually it looks like it hangs on the select, this prints in test and nothing more for me:

void main() {
  late TestDb db;

  setUp(() {
    db = TestDb();
  });

  tearDown(() async {
    print('tearDown');
    await db.close();
  });

  testWidgets('1', (tester) async {
    print('in test');
    expect(await selectOne(db), 1);
    print('after test');
  });
}

Do you rely on the fake async environment in your tests? If you're mainly testing the database you could wrap your whole test code in runAsync (or define a helper method like testAsyncWidgets).

@Mike278 I've applied the commit from master in the avoid-async-in-init branch.

[kuhnroyal]

Hmm prints

in test
after test
tearDown

for me :/
But is stuck afterwards.

[Mike278]

@Mike278 I've applied the commit from master in the avoid-async-in-init branch.

Thanks for doing this. Unfortunately no luck - same test failures as before. There must be something missing from the repro in the OP - I'll try to make some time in the next day or 2 to have a look.

[Mike278]

I tried again to minimize some of the real tests that are failing and this is what I came up with:

import 'dart:async';

import 'package:flutter/material.dart';
import 'package:flutter_test/flutter_test.dart';
import 'package:moor/ffi.dart';
import 'package:moor/moor.dart';

class TestDb extends GeneratedDatabase {
  TestDb() : super(SqlTypeSystem.withDefaults(), VmDatabase.memory());
  @override
  final List<TableInfo> allTables = const [];
  @override
  final int schemaVersion = 1;
}

Stream<int> selectOne(TestDb _db) => _db
  .customSelect('select 1 a')
  .map((row) => row.read<int>('a'))
  .watchSingle();

void main() {
  TestDb db;

  setUp(() async {
    db = TestDb();
    await db.customSelect('select 1 a').getSingle(); // 1
  });

  tearDown(() async {
    await db.close();
  });

  testWidgets('test 1', (tester) async {
    await tester.pumpWidget( // 2
      MaterialApp(
        home: StreamBuilder<int>(
          stream: selectOne(db),
          builder: (context, value) => Text('$value'),
        ),
      )
    );
    await tester.runAsync(() async {
      expect(await selectOne(db).first, 1);
    });
  });

  testWidgets('test 2', (tester) async {
    selectOne(db).listen(print); // 3
    await tester.runAsync(() async {
      expect(await selectOne(db).first, 1);
    });
  });

  // always passes
  testWidgets('test 3', (tester) async {
    await tester.runAsync(() async {
      selectOne(db).listen(print);
      expect(await selectOne(db).first, 1);
    });
  });

}

Commenting out lines //1, //2, and //3 individually yields surprising and very different results for tests 1 and 2... in some cases I get Flutter's "pending timers" failure, in some cases the expect(await selectOne(db).first, 1); still hangs, and in other cases it completes. I'm a little surprised that the //1 effects the results though - I guess it's because it changes when the db is actually opened?