WidgetsBinding.drawFrame falsely assumes that sendFramesToEngine won't turn from true to false #144261

During WidgetsBinding.drawFrame, a firstFrameCallback is scheduled to be called on the next timing report. The firstFrameCallback asserts that sendFramesToEngine is true. While this assertion might seem reasonable at a glance, since a timing report is called only after Rasterizer renders a frame, which requires sendFramesToEngine to be true, it's wrong. The assertion can be triggered if sendFramesToEngine turns from true to false between when the frame is sent to the engine and when the timing report callback is invoked.

While the case where sendFramesToEngine turns false right before firstFrameCallback is fired is extremely rare, the assumption is inherently wrong and should be fixed. We can assert that the sendFramesToEngine value when the callback was registered must be true, but not that it hasn't turned false when the callback is invoked.

Analysis

This problem was discovered in an internal test. The test is very simple, something like

  testWidgets('Culprit test', (tester) async {
    runApp(LocaleApp());
    await tester.pump();
  });

where LocaleApp is a widget that uses the localization API provided by MaterialApp, or simply, the Localization widget.

When the test is run on a live device, it crashes with the following log:

'package:flutter/src/widgets/binding.dart': Failed assertion: line 968 pos 16: 'sendFramesToEngine': is not true.
When the exception was thrown, this was the stack:
dart:core-patch/errors_patch.dart 51:61            _AssertionError._doThrowNew
dart:core-patch/errors_patch.dart 40:5             _AssertionError._throwNew
package:flutter/src/widgets/binding.dart 968:16    WidgetsBinding.drawFrame.<fn>
package:flutter/src/scheduler/binding.dart 343:19  SchedulerBinding._executeTimingsCallbacks
dart:ui/hooks.dart 328:13                          _invoke1
dart:ui/platform_dispatcher.dart 611:5             PlatformDispatcher._reportTimings
dart:ui/hooks.dart 278:31                          _reportTimings

Deeper analysis shows that this problem is a combination of testWidgets, live device testing, runApp, and deferFirstFrame. The deferFirstFrame method is used by the Localization widget, so that the widget can be built to fetch the locale data, while the resultant layer tree with invalid locale data will not be sent.

The sendFramesToEngine can turn false only if deferFirstFrame is called when no frame has been rendered yet. But if no frame has been rendered yet, how can there be a timing reporting callback, which is only invoked when a frame is rendered?

This is because testWidgets does some preparation before running a test body: It pumps a dummy widget, then calls resetFirstFrameSent.

The pumped dummy widget is guaranteed rendered, and leaves a timing reporting callback on hold. This creates an inconsistent state at start of the test body: there's a timing report callback pending (since the UI thread has not awaited yet), but the framework thinks that no frame is sent.

Now, if the test body uses runApp (instead of tester.pump) so that the widget tree is attached but no frame is rendered, and builds the widget tree, which defers the first frame, and then await, then the timing report callback will be invoked, finding the current value of sendFramesToEngine is false!

Apparently, the testWidgets leaking the timing reporting callback from the preparation is also a problem, and fixing either testWidgets or WidgetTester can solve the crash, but the WidgetTester should be of higher priority because:

1. WidgetTester is a production class
2. The assumption of WidgetTester is 100% wrong
3. It might not be trivial to fix: we might not be able to simply waiting for waitUntilFirstFrameRasterized since a warm-up frame might never be rendered.

This issue might be related to #132969