Mac tool_integration_tests_3_4 is 2.02% flaky #146879

fluttergithubbot · 2024-04-17T10:00:38Z

The post-submit test builder Mac tool_integration_tests_3_4 had a flaky ratio 2.02% for the past (up to) 100 commits, which is above our 2.00% threshold.

One recent flaky example for a same commit: https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/16001
Commit: c3445dc

Flaky builds:
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/16001
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/15916

Recent test runs:
https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac%20tool_integration_tests_3_4

Please follow https://github.com/flutter/flutter/wiki/Reducing-Test-Flakiness#fixing-flaky-tests to fix the flakiness and enable the test back after validating the fix (internal dashboard to validate: go/flutter_test_flakiness).

The text was updated successfully, but these errors were encountered:

christopherfujino · 2024-04-23T20:09:04Z

These look very similar to #145812 (comment), but

19:25 +8 -1: test/integration.shard/vmservice_integration_test.dart: Flutter Tool VMService method hotRestart can be called [E]
  TimeoutException after 0:15:00.000000: Test timed out after 15 minutes.

https://logs.chromium.org/logs/flutter/buildbucket/cr-buildbucket/8750489356623213857/+/u/run_test.dart_for_tool_integration_tests_shard_and_subshard_3_4/stdout

fluttergithubbot · 2024-05-01T09:10:11Z

[prod pool] flaky ratio for the past (up to) 100 commits between 2024-04-23 and 2024-04-30 is 1.01%. Flaky number: 1; total number: 99.
One recent flaky example for a same commit: https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/16208
Commit: 241078a
Flaky builds:
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/16208

Recent test runs:
https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac%20tool_integration_tests_3_4

In service of #146879 and #145812. In these issues, we see what appears to be the flutter tool getting stuck somewhere during hot reload. It may help if we knew were exactly where we are getting stuck (preparing assets, writing them to device, etc.). This PR adds a new parameter to `FlutterTestDriver::run`, `verbose`. When verbose is set, `FlutterTestDriver` will run `flutter` with `--verbose` in its tests. Keep in mind that `FlutterTestDriver` only prints logs from `flutter` when a test fails, so this shouldn't spam the logs of passing tests. This PR sets the parameter when invoking the flaky tests from #146879 and #145812, so we should see more detailed logs in future flakes. While this is a low risk PR, you can verify the change by intentionally breaking hot reload code, clearing the cached tool binaries, and then running either of these tests.

fluttergithubbot · 2024-05-08T09:10:09Z

[prod pool] flaky ratio for the past (up to) 100 commits between 2024-05-01 and 2024-05-07 is 1.01%. Flaky number: 1; total number: 99.
One recent flaky example for a same commit: https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/16274
Commit: abbaaea
Flaky builds:
https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/16274

Recent test runs:
https://flutter-dashboard.appspot.com/#/build?taskFilter=Mac%20tool_integration_tests_3_4

andrewkolos · 2024-05-08T17:59:25Z

Here is a recent failure (5/4):

https://ci.chromium.org/ui/p/flutter/builders/prod/Mac%20tool_integration_tests_3_4/16348/overview

and a quick link to one of the flaky tests:

flutter/packages/flutter_tools/test/integration.shard/vmservice_integration_test.dart

Line 77 in 13beab1

testWithoutContext('hotRestart can be called', () async {

From the logs, it seems we get to stuck somewhere in HotRunner::_restartFromSources.

Interestingly, if I'm reading things correctly, it appears that the app restart just fine since we see the app print twice:

<=stdout=  [  +34 ms] topLevelFunction

109s <=stdout=  [ +497 ms] topLevelFunction

I'll be adding some more traces very soon to try to narrow down where we get stuck.

In service of #146879 and #145812. This PR adds some more traces to help us figure out where we are getting blocked. See #146879 (comment) for more context.

andrewkolos · 2024-05-12T19:14:40Z

With #147997 landing, we are getting some new information here. Here is an example (quick link to logs).

In the logs, we see we get far enough to print Finished waiting on operations. (callsite), but we don't see the Hot restart performed in Xms that should come shortly after. Given this, I believe the tool is getting stuck somewhere in HotRunner::_launchFromDevFS. The only long-running/async operation I see within is _launchInView, which in turn makes two VM service calls, _flutter.listViews and _flutter.runInView. However, I don't see either of these outgoing calls the logs¹, which is really confusing.

From what I can tell, any communications to and from the VM service should appear in the log. Documentation. We see that we listen to communications by listening to some broadcast streams exposed by the VM service here, and we see that any VM service call should write to the onSend stream here. Are we never getting to this line? ↩

andrewkolos · 2024-05-13T20:55:36Z

The only long-running/async operation I see within is _launchInView, which in turn makes two VM service calls, _flutter.listViews and _flutter.runInView. However, I don't see either of these outgoing calls the logs1, which is really confusing.

I tried running the test locally with a working emulator. Even then, _flutter.listViews or _flutter.runInView don't appear in the logs, so I simply don't understand something there. Regardless, this means that these calls might be occurring as they should, but they might be getting stuck or that listViews is yielding an empty list.

In service of #146879. See #146879 (comment) in particular for the purpose of this PR. This adds a few more `printTrace` calls to try to see where we are getting stuck.

andrewkolos · 2024-05-14T17:39:20Z

From the logs of a recent failure, I see
Finished _flutter.runInView, but I do not see Finished running <path here>/main.dart.dill in view _flutterView/0x7f8fc781e420.... I believe the tool is getting stuck here in FlutterVmService::runInView:

flutter/packages/flutter_tools/lib/src/vmservice.dart

Line 593 in 7d26350

await onRunnable;

Here is the definition of this future for quick reference:

flutter/packages/flutter_tools/lib/src/vmservice.dart

Lines 580 to 582 in 7d26350

    
           final Future<void> onRunnable = service.onIsolateEvent.firstWhere((vm_service.Event event) { 
        
             return event.kind == vm_service.EventKind.kIsolateRunnable; 
        
           });

The next step is to figure out why we are rarely not getting an IsolateRunnable event from the VM service. Perhaps we aren't listening properly?

In service of #146879. See #146879 (comment). I wonder if something is going wrong in the process of subscribing to the isolate event stream in the VM service. This adds a print trace to the `catch` clause of this subscription call.

andrewkolos · 2024-05-14T21:26:03Z

Downgrading to P1 since flakiness is under the 2% treshold.

andrewkolos · 2024-05-18T04:08:16Z

Another more recent log with more prints. Here we see Error: streamListen: (103) Stream already subscribed, which means that the tool is properly listening for isolate events.

Reading the logs more carefully, I see the IsolateRunnable event:

<=vm=      {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Isolate","event":{"type":"Event","kind":"IsolateRunnable","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/2422844065420505","name":"main.dart","number":"2422844065420505","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/762944440870147","name":"main","number":"762944440870147","isSystemIsolate":false,"isolateGroupId":"isolateGroups/2422844065420505"},"timestamp":1715853445413}}}

Here is what is printing this:

flutter/packages/flutter_tools/test/integration.shard/test_driver.dart

Line 142 in 13beab1

_vmService!.onReceive.listen((String s) => _debugPrint(s, topic: '<=vm='));

This appears after we make the _flutter.runInView call, so it seems like the event is occurring, yet onRunnable never completes.

flutter/packages/flutter_tools/lib/src/vmservice.dart

Lines 580 to 582 in 7d26350

    
           final Future<void> onRunnable = service.onIsolateEvent.firstWhere((vm_service.Event event) { 
        
             return event.kind == vm_service.EventKind.kIsolateRunnable; 
        
           });

This begs the question: is something wrong with VmService::onIsolateEvent? What if we listened to onReceive (and parsed for IsolateRunnable) instead of listening to onIsolateEvent? I think this is worth continued investigation in case there is some bug in package:vm_service or, even worse, Dart streams.

…48596) In service of #146879. Please see #146879 (comment). In summary, when the test flakes, `onRunnable` is not completing despite the VmService object receiving an `IsolateRunnable` event. This PR adds some logging code to print all events received inside of `FlutterVmService::runInView`.

fluttergithubbot · 2024-05-22T09:10:07Z

[prod pool] flaky ratio for the past (up to) 100 commits between 2024-05-14 and 2024-05-21 is 0.00%. Flaky number: 0; total number: 100.

fluttergithubbot · 2024-05-29T09:10:09Z

[prod pool] flaky ratio for the past (up to) 100 commits between 2024-05-21 and 2024-05-28 is 0.00%. Flaky number: 0; total number: 98.

fluttergithubbot · 2024-06-05T09:10:09Z

[prod pool] flaky ratio for the past (up to) 100 commits between 2024-05-28 and 2024-06-04 is 0.00%. Flaky number: 0; total number: 99.

…logged incoming messages (#149756) In service of #146879. In summary, a bunch of `printTrace` calls were added to try to troubleshoot this flake, but the flake has stopped happening. This PR more-or-less reverts #148596, since this was the only change that could have _theoretically_ (somehow maybe) stopped the flake. I'll consider reverting the rest of the `printTrace` calls if the flake does not reappear after this PR lands.

fluttergithubbot · 2024-06-12T09:10:12Z

[prod pool] flaky ratio for the past (up to) 100 commits between 2024-06-05 and 2024-06-11 is 0.00%. Flaky number: 0; total number: 95.

fluttergithubbot added c: flake Tests that sometimes, but not always, incorrectly pass P0 Critical issues such as a build break or regression team-tool Owned by Flutter Tool team labels Apr 17, 2024

fluttergithubbot assigned christopherfujino Apr 17, 2024

christopherfujino assigned andrewkolos and unassigned christopherfujino Apr 30, 2024

andrewkolos mentioned this issue May 1, 2024

add verbose logging to select hot reload/hot restart tests #147673

Merged

9 tasks

andrewkolos added the triaged-tool Triaged by Flutter Tool team label May 8, 2024

This was referenced May 8, 2024

Mac tool_integration_tests_2_4 is 2.04% flaky #145812

Open

add print traces to reload isolate resume logic #147997

Merged

auto-submit bot pushed a commit that referenced this issue May 8, 2024

add print traces to reload isolate resume logic (#147997)

2cfae14

In service of #146879 and #145812. This PR adds some more traces to help us figure out where we are getting blocked. See #146879 (comment) for more context.

elliette mentioned this issue May 9, 2024

Flutter web integration tests failing flutter/devtools#7732

Open

andrewkolos mentioned this issue May 13, 2024

add more print traces in hot runner workflow #148258

Merged

9 tasks

andrewkolos mentioned this issue May 14, 2024

add another print trace to runInView #148337

Merged

9 tasks

andrewkolos added P1 High-priority issues at the top of the work list and removed P0 Critical issues such as a build break or regression labels May 14, 2024

andrewkolos mentioned this issue May 18, 2024

log incoming vm service messages in FlutterVMService::runInView #148596

Merged

9 tasks

andrewkolos mentioned this issue Jun 5, 2024

[flutter_tools] Remove additional listener on VM service that simply logged incoming messages #149756

Merged

9 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Mac tool_integration_tests_3_4 is 2.02% flaky #146879

Mac tool_integration_tests_3_4 is 2.02% flaky #146879

fluttergithubbot commented Apr 17, 2024

christopherfujino commented Apr 23, 2024

fluttergithubbot commented May 1, 2024

fluttergithubbot commented May 8, 2024

andrewkolos commented May 8, 2024

andrewkolos commented May 12, 2024 •

edited

andrewkolos commented May 13, 2024

andrewkolos commented May 14, 2024

andrewkolos commented May 14, 2024

andrewkolos commented May 18, 2024 •

edited

fluttergithubbot commented May 22, 2024

fluttergithubbot commented May 29, 2024

fluttergithubbot commented Jun 5, 2024

fluttergithubbot commented Jun 12, 2024

Mac tool_integration_tests_3_4 is 2.02% flaky #146879

Mac tool_integration_tests_3_4 is 2.02% flaky #146879

Comments

fluttergithubbot commented Apr 17, 2024

christopherfujino commented Apr 23, 2024

fluttergithubbot commented May 1, 2024

fluttergithubbot commented May 8, 2024

andrewkolos commented May 8, 2024

andrewkolos commented May 12, 2024 • edited

Footnotes

andrewkolos commented May 13, 2024

andrewkolos commented May 14, 2024

andrewkolos commented May 14, 2024

andrewkolos commented May 18, 2024 • edited

fluttergithubbot commented May 22, 2024

fluttergithubbot commented May 29, 2024

fluttergithubbot commented Jun 5, 2024

fluttergithubbot commented Jun 12, 2024

andrewkolos commented May 12, 2024 •

edited

andrewkolos commented May 18, 2024 •

edited