Windows smoke test: fix the crash-loop flake

.github/workflows/ci.yaml

@@ -149,30 +149,46 @@ jobs:
           }
       - name: Runtime smoke test (example app, real cef_host)
         # Runs the app against the cef_host it just built: first frame, eval, a
-        # JS channel, resize, freeze/thaw. Once as the runner composites, once
-        # with the GPU off (software paint). See
-        # example/lib/windows_smoke_probe.dart.
+        # JS channel, resize, freeze/thaw, and a crash loop on one of two tiles
+        # sharing a host. Once as the runner composites, once with the GPU off
+        # (software paint). The plugin's and hosts' log lines go to a file
+        # (FLUTTER_CEF_LOG_FILE); the crash-loop lines are printed, and the
+        # whole log when a mode fails. See example/lib/windows_smoke_probe.dart.
         shell: pwsh
-        timeout-minutes: 15
+        timeout-minutes: 20
         run: |
           cd example
           flutter build windows --debug -t lib/windows_smoke_probe.dart
           if ($LASTEXITCODE -ne 0) { exit $LASTEXITCODE }
+          $env:FLUTTER_CEF_SMOKE_CRASH_ROUNDS = "3"
           $failed = $false
           foreach ($mode in @("default", "software")) {
             if ($mode -eq "software") { $env:FLUTTER_CEF_SOFTWARE_COMPOSITING = "1" }
             $out = Join-Path $env:RUNNER_TEMP "windows_smoke_$mode.txt"
+            $log = Join-Path $env:RUNNER_TEMP "windows_smoke_$mode.log"
             $env:FLUTTER_CEF_PROBE_OUT = $out
+            $env:FLUTTER_CEF_LOG_FILE = $log
             $p = Start-Process -FilePath "build\windows\x64\runner\Debug\flutter_cef_example.exe" -PassThru
-            $timedOut = -not $p.WaitForExit(240000)
+            $timedOut = -not $p.WaitForExit(300000)
             if ($timedOut) {
               Stop-Process -Id $p.Id -Force -ErrorAction SilentlyContinue
               Get-Process cef_host -ErrorAction SilentlyContinue | Stop-Process -Force -ErrorAction SilentlyContinue
             }
             Write-Output "== smoke test, $mode compositing"
             if (Test-Path $out) { Get-Content $out }
-            if ($timedOut) { Write-Output "timed out after 240 s"; $failed = $true }
-            elseif (-not (Test-Path $out)) { Write-Output "no result file at $out"; $failed = $true }
-            elseif (-not (Select-String -Path $out -Pattern "CEF_PROBE_RESULT PASS" -Quiet)) { $failed = $true }
+            $modeFailed = $false
+            if ($timedOut) { Write-Output "timed out after 300 s"; $modeFailed = $true }
+            elseif (-not (Test-Path $out)) { Write-Output "no result file at $out"; $modeFailed = $true }
+            elseif (-not (Select-String -Path $out -Pattern "CEF_PROBE_RESULT PASS" -Quiet)) { $modeFailed = $true }
+            if (Test-Path $log) {
+              if ($modeFailed) {
+                Write-Output "== plugin and host log, $mode compositing"
+                Get-Content $log
+              } else {
+                Write-Output "== host crash-loop lines, $mode compositing"
+                Select-String -Path $log -Pattern "renderer terminated|giving up|several browsers|browser gone" | ForEach-Object { $_.Line }
+              }
+            }
+            if ($modeFailed) { $failed = $true }
           }
           if ($failed) { exit 1 }

CHANGELOG.md

@@ -1,3 +1,11 @@
+## Unreleased
+
+* **Windows logs to a file on request**: set `FLUTTER_CEF_LOG_FILE` to a path
+  and the plugin appends its own and every `cef_host`'s log lines there (they
+  otherwise go only to `OutputDebugString`).
+* The Windows runtime smoke test's crash-loop case no longer depends on the
+  network or a fixed pace, and CI prints the host's side of it.
+
 ## 0.3.0
 
 * **Windows catches up with macOS**: `sessionStats`, `setAudioMuted`,

example/lib/windows_smoke_probe.dart

@@ -47,7 +47,6 @@ const _html = '''<!doctype html><meta charset="utf-8">
 // isolation gives each its own renderer process and killing one can't take
 // the other with it.
 const _sentinelUrl = 'https://flutter-cef-sentinel.test/';
-const _victimUrl = 'https://flutter-cef-victim.test/';
 
 void main() => runApp(const MaterialApp(home: ProbeApp()));
 
@@ -209,33 +208,64 @@ class _ProbeAppState extends State<ProbeApp> {
       _check('probe ran to completion', false, '$e\n$st');
     }
     await c.dispose();
-    await _crashLoop();
+    await _crashLoops();
     _finish();
   }
 
+  /// Polls [done] until it is true or [within] has passed.
+  Future<bool> _waitFor(bool Function() done, Duration within) async {
+    final sw = Stopwatch()..start();
+    while (!done()) {
+      if (sw.elapsed >= within) return false;
+      await Future<void>.delayed(const Duration(milliseconds: 20));
+    }
+    return true;
+  }
+
   /// A tile whose renderer keeps crashing ends alone; its neighbour on the
-  /// same host carries on.
-  Future<void> _crashLoop() async {
-    const group = 'windows-smoke-crash-loop';
+  /// same host carries on. FLUTTER_CEF_SMOKE_CRASH_ROUNDS runs it more than
+  /// once, each round on a fresh host.
+  Future<void> _crashLoops() async {
+    final rounds =
+        int.tryParse(
+          Platform.environment['FLUTTER_CEF_SMOKE_CRASH_ROUNDS'] ?? '',
+        ) ??
+        1;
+    for (var round = 1; round <= rounds; round++) {
+      await _crashLoop(round);
+    }
+  }
+
+  Future<void> _crashLoop(int round) async {
+    final tag = 'crash loop $round';
+    final group = 'windows-smoke-crash-loop-$round';
     final sentinel = CefWebController(hostGroup: group);
     final victim = CefWebController(hostGroup: group);
+    // A timeline of the victim's side, printed with the result.
+    final clock = Stopwatch()..start();
+    void event(String what) =>
+        _log('  $tag +${clock.elapsedMilliseconds}ms $what');
     String? sentinelGone;
     final victimGone = Completer<String>();
-    final sentinelLoaded = Completer<void>();
-    final victimLoaded = Completer<void>();
+    var sentinelLoaded = false;
+    var victimFinishes = 0;
     sentinel.onProcessGone = (r) => sentinelGone ??= r;
+    sentinel.onPageFinished = (_) => sentinelLoaded = true;
     victim.onProcessGone = (r) {
+      event('victim processGone($r)');
       if (!victimGone.isCompleted) victimGone.complete(r);
     };
-    sentinel.onPageFinished = (_) {
-      if (!sentinelLoaded.isCompleted) sentinelLoaded.complete();
-    };
     victim.onPageFinished = (_) {
-      if (!victimLoaded.isCompleted) victimLoaded.complete();
+      victimFinishes++;
+      event('victim pageFinished');
     };
-    var victimLoads = 0;
-    victim.onPageStarted = (_) => victimLoads++;
+    victim.onLoadError = (e) => event('victim loadError ${e.errorText}');
     try {
+      // The sentinel is served at an https origin and the victim is a data:
+      // page: different sites, so each gets its own renderer. A data: page
+      // also reloads without the network. (An authored victim loses its
+      // document at the first navigate, so its reloads went to DNS and came
+      // back as error pages, which report no pageStarted.)
       await sentinel.create(
         url: _sentinelUrl,
         html: _html,
@@ -244,40 +274,49 @@ class _ProbeAppState extends State<ProbeApp> {
         height: 240,
       );
       await victim.create(
-        url: _victimUrl,
+        url: 'about:blank',
         html: _html,
-        htmlBaseUrl: _victimUrl,
         width: 320,
         height: 240,
       );
-      final loaded =
-          await Future.wait([sentinelLoaded.future, victimLoaded.future])
-              .then((_) => true)
-              .timeout(const Duration(seconds: 60), onTimeout: () => false);
-      _check('crash loop: both tiles load', loaded);
+      _check(
+        '$tag: both tiles load',
+        await _waitFor(
+          () => sentinelLoaded && victimFinishes > 0,
+          const Duration(seconds: 60),
+        ),
+      );
 
       // chrome://kill is a renderer debug URL: Chromium ends the tile's
       // renderer (exit code 1, no crash dump) and cef_host reloads the page.
-      // Four deaths within 10 s and the host gives up on the tile.
-      for (var i = 0; i < 8 && !victimGone.isCompleted; i++) {
+      // Each kill waits for that reload to finish, or for processGone, before
+      // the next, so every kill lands on a live, loaded page; one that shows
+      // neither within 5 s is sent again. Four deaths within 10 s and the host
+      // gives up on the tile.
+      var kills = 0;
+      while (!victimGone.isCompleted &&
+          clock.elapsed < const Duration(seconds: 90)) {
+        final finishes = victimFinishes;
+        kills++;
+        event('kill $kills');
         await victim.navigate('chrome://kill');
-        await victimGone.future
-            .then((_) {})
-            .timeout(const Duration(seconds: 1), onTimeout: () {});
+        await _waitFor(
+          () => victimGone.isCompleted || victimFinishes > finishes,
+          const Duration(seconds: 5),
+        );
       }
-      final gone = await victimGone.future.timeout(
-        const Duration(seconds: 15),
-        onTimeout: () => '<none; the victim loaded $victimLoads times>',
-      );
+      final gone = victimGone.isCompleted
+          ? await victimGone.future
+          : '<none after $kills kills>';
       _check(
-        'crash loop: the crash-looping tile gets processGone(crashed)',
+        '$tag: the crash-looping tile gets processGone(crashed)',
         gone == 'crashed',
         gone,
       );
 
       final before = await _presents(sentinel);
       _check(
-        'crash loop: the other tile on the host keeps painting',
+        '$tag: the other tile on the host keeps painting',
         await _presentsPast(
           sentinel,
           before,
@@ -288,14 +327,14 @@ class _ProbeAppState extends State<ProbeApp> {
       final four = await sentinel
           .runJavaScriptReturningResult('2 + 2')
           .timeout(const Duration(seconds: 10));
-      _check('crash loop: the other tile answers evals', '$four' == '4', four);
+      _check('$tag: the other tile answers evals', '$four' == '4', four);
       _check(
-        'crash loop: the other tile gets no processGone',
+        '$tag: the other tile gets no processGone',
         sentinelGone == null,
         sentinelGone,
       );
     } catch (e, st) {
-      _check('crash loop case ran to completion', false, '$e\n$st');
+      _check('$tag: ran to completion', false, '$e\n$st');
     }
     await sentinel.dispose();
     await victim.dispose();

packages/flutter_cef_windows/CHANGELOG.md

@@ -1,3 +1,13 @@
+## Unreleased
+
+* `FLUTTER_CEF_LOG_FILE=<path>` appends the plugin's and every `cef_host`'s log
+  lines to that file, each with a millisecond tick, as well as sending them to
+  `OutputDebugString`.
+* CI: the smoke test's crash-loop case kills the tile's renderer only once the
+  previous reload has finished, re-sends a kill that didn't take, and uses a
+  `data:` page so a reload never goes to the network. It runs 3 rounds per
+  compositing mode and prints the host's crash-loop log lines.
+
 ## 0.1.0
 
 * Authored documents at a real origin (`kOpSetAuthoredHtml` 0x3f and the

packages/flutter_cef_windows/README.md

@@ -68,6 +68,14 @@ rasterizer) when there is none. `<select>` dropdowns are drawn over the view.
 Chromium paints in software. It is how CI covers the software path, and it
 helps tell a GPU-driver problem from a page problem.
 
+## Logs
+
+The plugin writes its own log lines and those of every `cef_host` (renderer
+crashes, a host giving up on a tile, pipe failures) with `OutputDebugString`,
+so a debugger or DebugView shows them. Set `FLUTTER_CEF_LOG_FILE` to a file
+path to have them appended there as well, each with a millisecond tick; CI
+uses it to print the host's side of the smoke test.
+
 ## Layout
 
 - `lib/flutter_cef_windows.dart` — `registerWith()` endorsing the shared

packages/flutter_cef_windows/windows/flutter_cef_plugin.cpp

@@ -60,8 +60,26 @@ UINT WatchdogGraceMs() { return EnvMs(L"FLUTTER_CEF_FIRSTPAINT_MS", 10000); }
 UINT LivenessStalenessMs() { return EnvMs(L"FLUTTER_CEF_LIVENESS_MS", 10000); }
 UINT LivenessHangMs() { return EnvMs(L"FLUTTER_CEF_HANG_MS", 15000); }
 
+// The plugin's and the hosts' log lines go to OutputDebugString. When
+// FLUTTER_CEF_LOG_FILE names a file they are also appended there, with a
+// millisecond tick, for where no debugger is attached (CI).
 void Log(const std::string& msg) {
-  OutputDebugStringA(("[flutter_cef_windows] " + msg + "\n").c_str());
+  const std::string line = "[flutter_cef_windows] " + msg + "\n";
+  OutputDebugStringA(line.c_str());
+  static const std::wstring log_file = [] {
+    wchar_t buf[MAX_PATH] = {};
+    const DWORD n =
+        GetEnvironmentVariableW(L"FLUTTER_CEF_LOG_FILE", buf, MAX_PATH);
+    return n > 0 && n < MAX_PATH ? std::wstring(buf, n) : std::wstring();
+  }();
+  if (log_file.empty()) return;
+  static std::mutex log_mutex;
+  std::lock_guard<std::mutex> lock(log_mutex);
+  FILE* f = nullptr;
+  if (_wfopen_s(&f, log_file.c_str(), L"ab") != 0 || !f) return;
+  fprintf(f, "%llu %s", static_cast<unsigned long long>(GetTickCount64()),
+          line.c_str());
+  fclose(f);
 }
 
 // Verbs the macOS plugin serves that Windows has no host support for. They