diff --git a/CHANGELOG.md b/CHANGELOG.md index 6d13df0..9aed194 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,16 @@ This project follows [Semantic Versioning 2.0.0](https://semver.org/spec/v2.0.0. ## [Unreleased] +### Added + +- **`ExtensionNotRegisteredException` and `ArtisanCommand.exitTryAgain` (75).** `VmServiceClient.callServiceExtension` (and so `ArtisanContext.callExtension`) throws `ExtensionNotRegisteredException` when the app answers JSON-RPC `-32601`, so a command can tell "not registered yet" from a failed call without importing `package:vm_service` (which trips `depend_on_referenced_packages` in a consumer). `exitTryAgain` is `EX_TEMPFAIL` from `sysexits.h`: the exit code for "not ready yet, retry". (`lib/src/vm/`, `lib/src/console/artisan_command.dart`) + +### Fixed + +- **A connected command calling an extension the app has not registered prints one line, not an RPC stack.** Run while the app was still booting, `player:state` printed `Connected command player:state failed: ext.watchools.player: (-32601) Method not found` and a vm_service stack, then worked a few seconds later. The dispatcher now prints `ext.watchools.player is not registered in the running app yet (still booting, a release build, or the plugin is not installed). Retry in a few seconds.` and exits 75. Every other RPC error keeps the unexpected-failure path (exit 3, with the stack). The mapping covers the retries inside `callServiceExtension` too, so a hot restart whose fresh isolate has not registered its extensions yet gets the same line. The mapping applies where the runtime answers `-32601` (the Dart VM, and the Chrome proxy in DWDS 27); a web runtime that reports a missing extension with another code keeps the old output. (`lib/src/vm/vm_service_client.dart`, `lib/src/console/artisan_application.dart`, `test/`) + +- **`start` on a cold native build no longer exits on a stack fragment when `--timeout` runs out.** A first macOS build (CocoaPods, SwiftPM) outlasts the 90s scrape, and the timeout's `StateError` escaped as an unexpected error whose visible tail was ``, while the app kept building and the next connected command recovered the URI from the log. The plain branch now checks the `flutter run` pid: alive, it prints `flutter run (pid ) is still building after s` with the `artisan status`, retry and `--timeout` hints, keeps the booting session and exits 75; gone, it reports that `flutter run` exited before announcing a URI, names the log, stops the FIFO holder, removes the session and exits 1. A connected command against a booting session whose `flutter run` is still alive exits 75 as well (it was 1), so a caller can retry on one code from `start` to the first command that connects. The scrape loop throws `TimeoutException` instead of `StateError`; the `--cdp-port` branch still fails and reaps on a timeout, and prints the timeout's message without the `TimeoutException after ` prefix. (`lib/src/commands/start_command.dart`, `test/commands/start_command_early_state_test.dart`, `doc/commands/start.md`) + ## [0.0.19] - 2026-10-09 ### Changed diff --git a/doc/commands/start.md b/doc/commands/start.md index 17b7d9a..9aa2e59 100644 --- a/doc/commands/start.md +++ b/doc/commands/start.md @@ -46,7 +46,7 @@ dart run artisan start [--device=] [--port=] [--vm-service-port=] | `--dds` | flag | `false` | Enable Dart Development Service. When absent (default), `--no-dds` is forwarded to `flutter run` so dusk and tinker connect directly to the VM Service. | | `--profile-static` | flag | `false` | Start a static-profile run. Sets `profile: "static"` in `state.json`; otherwise `"debug"`. On a device (Android, iOS, desktop) it also forwards `--profile` to `flutter run`, once even when `--flutter-arg=--profile` is passed too; there is no hot reload in that mode. On Chrome it stays a label, because a web profile build has no VM Service. `restart` replays it from `state.json`; `restart --no-profile-static` drops it. | | `--cdp-port` | int | (none) | Chrome DevTools Protocol port. When set, `start` pre-launches Chrome with `--remote-debugging-port=` and runs Flutter on `-d web-server`, recording `chromePid` / `tmpProfileDir` / `cdpPort` in `state.json`. Required for `dusk:resize` / `dusk:device`. Only valid with `--device=chrome` or `--device=web-server`, and requires Flutter SDK 3.30.0 or newer. A subsequent `restart` preserves this port. The port is probed before Chrome launches; if it is already in use you receive a clear error with the `--cdp-port` hint instead of a misleading "Is Chrome installed?" message. | -| `--timeout` | int | `90` | Seconds to wait for the VM Service URI to appear in the `flutter run` log. Increase on cold starts where build and DartDev initialisation takes longer than the default (common on first run after a clean Flutter SDK install or on low-powered CI). Applies to the `--cdp-port` branch and to the plain one alike; on the `--cdp-port` branch it also bounds the wait for the web server's `is being served at` line, which used to be a fixed 60 seconds and failed a web compile that ran long under load. | +| `--timeout` | int | `90` | Seconds to wait for the VM Service URI to appear in the `flutter run` log. Increase on cold starts where build and DartDev initialisation takes longer than the default (common on first run after a clean Flutter SDK install or on low-powered CI). On the plain branch a timeout while `flutter run` is still alive exits `75` and leaves the session recording (see [Troubleshooting](#troubleshooting)). Applies to the `--cdp-port` branch and to the plain one alike; on the `--cdp-port` branch it also bounds the wait for the web server's `is being served at` line, which used to be a fixed 60 seconds and failed a web compile that ran long under load. | | `--flutter-arg` | string | (none) | Extra argument forwarded verbatim to `flutter run`, repeatable. Use it for anything `start` has no flag of its own for: `--flutter-arg=--dart-define=KEY=VALUE`, `--flutter-arg=--flavor=dev`, `--flutter-arg=--web-renderer=html`. Forwarded AFTER the arguments `start` builds, so a repeated flag overrides the default it chose. A value containing commas is kept whole (`splitCommas` is off), so `--flutter-arg=--dart-define=TAGS=a,b` reaches Flutter as one argument. Recorded in `state.json` as `flutterArgs` and replayed by `restart`; `restart --flutter-arg=` replaces the whole carried set, which is also how to clear one. | @@ -160,7 +160,14 @@ Allows up to 180 seconds for the VM Service URI to appear in the log. Use this w **`mkfifo` permission denied.** `start` creates the FIFO at `~/.artisan/flutter-dev.fifo`. If `~/.artisan/` was created by a previous run with different ownership or mode bits, `mkfifo` fails. Fix with `rm -rf ~/.artisan && dart run artisan start`. Note: `start` is POSIX-only (macOS/Linux). It will not work on Windows. -**VM Service URI never appears (timeout).** If `flutter run` stalls before printing the URI (for example, the Chrome binary is missing, the Flutter SDK is not on `PATH`, or a Dart compilation error occurs), `start` throws `StateError: Timed out after s...`. Inspect the log at `~/.artisan/flutter-dev.log` for the underlying Flutter output. Common causes: wrong `--device` value, missing `CHROME_EXECUTABLE` env var for headless environments, or a syntax error in the app's entry point. On cold starts (first run after a fresh SDK install, slow CI), increase the deadline with `--timeout=120` or higher. +**VM Service URI never appears (timeout).** When `--timeout` runs out before the URI shows up in the log, `start` checks whether `flutter run` is still alive. + +- **Still running (exit 75).** A first native build (CocoaPods, SwiftPM, Gradle) routinely takes longer than 90 seconds, and the app keeps building after `start` returns. `start` prints `flutter run (pid ) is still building after s ...` and exits `75` (`EX_TEMPFAIL`, `ArtisanCommand.exitTryAgain`), so a script can tell "not ready yet" from a failure. The session stays recorded with `booting: true`; `status` shows it, and the next connected command reads the URI from the log once the build finishes. A connected command run before that point also exits `75` while the recorded `flutter run` is alive, so a script can retry on the one code until it succeeds. Pass `--timeout=600` to make `start` itself wait for a cold build. +- **Exited (exit 1).** `flutter run` died before announcing a URI, almost always a build or launch error. `start` prints `flutter run (pid ) exited before announcing a VM Service URI` with the log path, stops the FIFO holder and removes the session (the log stays), so `status` does not report a dead app as booting. Common causes in `~/.artisan/flutter-dev.log`: a wrong `--device` value, a missing `CHROME_EXECUTABLE` env var in headless environments, or a compile error in the app's entry point. + +On the `--cdp-port` branch a timeout still fails the start with exit 1 and reaps Chrome and the flutter tool, since a web build has no long native phase to wait out. + +**Connected command reports an unregistered extension (exit 75).** A connected command that calls `ctx.callExtension('ext.')` before the app has registered that extension (the app is still booting, it is a release build, or the plugin is not installed in it) prints one line, `ext. is not registered in the running app yet (...). Retry in a few seconds.`, and exits `75`. The JSON-RPC `-32601` error reaches the command as `ExtensionNotRegisteredException`, so a command that wants to wait for the extension can catch it without importing `package:vm_service`. **Web server not ready in time (`--cdp-port`).** On the `--cdp-port` branch `start` waits for the `is being served at` line before it navigates Chrome, and fails with `Timed out after s waiting for "is being served at"`. The deadline is `--timeout`; raise it when the web compile is slow. The failed start stops the flutter tool's and Chrome's process groups and waits for their ports, so a retry straight after it does not collide with the leftovers. diff --git a/lib/artisan.dart b/lib/artisan.dart index f5ad7c9..81ed5d8 100644 --- a/lib/artisan.dart +++ b/lib/artisan.dart @@ -52,6 +52,7 @@ export 'src/extensions/register_extension_idempotent.dart'; export 'src/state/state_file.dart'; export 'src/state/vm_service_log.dart'; export 'src/stubs/stub_loader.dart'; +export 'src/vm/extension_not_registered_exception.dart'; export 'src/vm/vm_service_client.dart'; // Builtin commands (ship with artisan; the consumer's bin/dispatcher.dart diff --git a/lib/src/commands/start_command.dart b/lib/src/commands/start_command.dart index b98347e..7d85dc9 100644 --- a/lib/src/commands/start_command.dart +++ b/lib/src/commands/start_command.dart @@ -9,6 +9,7 @@ import '../console/artisan_command.dart'; import '../console/artisan_context.dart'; import '../console/command_boot.dart'; import '../console/pid_parser.dart'; +import '../console/process_alive.dart'; import '../console/shell_quote.dart'; import '../state/state_file.dart'; import '../state/vm_service_log.dart'; @@ -200,6 +201,11 @@ class StartCommand extends ArtisanCommand { @visibleForTesting static Duration cdpReapGrace = const Duration(seconds: 5); + /// Test seam: liveness check for the `flutter run` pid when the plain + /// branch's scrape times out (default [processAlive]). + @visibleForTesting + static bool Function(int pid) startIsAlive = processAlive; + /// Default [CdpPortProbe] implementation. Binds [ServerSocket] on /// [InternetAddress.loopbackIPv4] and immediately closes it. /// Returns `true` when the port is free; `false` on [SocketException] @@ -523,7 +529,19 @@ class StartCommand extends ArtisanCommand { ); await StateFile.write(booting); - final vmServiceUri = await _runVmServiceScrape(logFile, resolvedTimeout); + final String vmServiceUri; + try { + vmServiceUri = await _runVmServiceScrape(logFile, resolvedTimeout); + } on TimeoutException { + return _reportScrapeTimeout( + ctx, + childPid: childPid, + holderPid: holderPid, + fifoPath: fifoPath, + timeoutSeconds: resolvedTimeout, + logFile: logFile, + ); + } await StateFile.write(readyState(booting, vmServiceUri: vmServiceUri)); @@ -534,6 +552,46 @@ class StartCommand extends ArtisanCommand { return 0; } + /// Reports a scrape that ran out of time on the plain branch. + /// + /// A first native build (CocoaPods, SwiftPM, Gradle) routinely outlasts the + /// default 90s, and the app keeps building after this command returns: the + /// booting session stays on disk, and the next connected command reads the + /// URI back from the log. So a live `flutter run` is "not ready yet" + /// ([ArtisanCommand.exitTryAgain]), not a failure. A `flutter run` that is + /// gone exited before announcing a URI, almost always a build error, and the + /// log is where it says why. Its session is taken down with it (the FIFO + /// holder, the FIFO, the record) so `status` does not report a dead app as + /// booting; the log stays. + Future _reportScrapeTimeout( + ArtisanContext ctx, { + required int childPid, + required int holderPid, + required String fifoPath, + required int timeoutSeconds, + required File logFile, + }) async { + if (!startIsAlive(childPid)) { + cdpKillPid(holderPid); + final File fifo = File(fifoPath); + if (fifo.existsSync()) await fifo.delete(); + await StateFile.delete(); + ctx.output.error( + 'flutter run (pid $childPid) exited before announcing a VM Service ' + 'URI. See ${logFile.path} for the reason.', + ); + return 1; + } + ctx.output.warning( + 'flutter run (pid $childPid) is still building after ${timeoutSeconds}s ' + 'and has not announced a VM Service URI yet. The session is recorded: ' + 'run `artisan status`, or retry a connected command once the build ' + 'finishes. Pass --timeout= to wait longer. Log: ' + '${logFile.path}', + ); + return ArtisanCommand.exitTryAgain; + } + /// Handles the `--cdp-port=N` branch: validate, pre-launch Chrome, /// run flutter on web-server, scrape VM Service URI, navigate Chrome, /// write state. @@ -762,7 +820,11 @@ class StartCommand extends ArtisanCommand { // FIFO, no tmp profile dir, and holds none of the ports the retry // that usually follows will bind. The error surfaced to the operator // is the ORIGINAL throw, never a cleanup error. - ctx.output.error('CDP start failed after launch: $error'); + // A TimeoutException prints its Duration first; the message already + // names the deadline. + final Object reason = + error is TimeoutException ? (error.message ?? error) : error; + ctx.output.error('CDP start failed after launch: $reason'); await _reapAfterCdpFailure( ctx: ctx, flutterProcess: flutterProcess, @@ -1224,9 +1286,10 @@ class StartCommand extends ArtisanCommand { } await Future.delayed(const Duration(milliseconds: 250)); } - throw StateError( + throw TimeoutException( 'Timed out after ${timeoutSeconds}s waiting for VM Service URI in ' '${logFile.path}.', + Duration(seconds: timeoutSeconds), ); } diff --git a/lib/src/console/artisan_application.dart b/lib/src/console/artisan_application.dart index a174c4c..3312d13 100644 --- a/lib/src/console/artisan_application.dart +++ b/lib/src/console/artisan_application.dart @@ -5,6 +5,7 @@ import 'package:args/args.dart'; import '../helpers/console_style.dart'; import '../state/state_file.dart'; import '../state/vm_service_log.dart'; +import '../vm/extension_not_registered_exception.dart'; import '../vm/vm_service_client.dart'; import 'artisan_command.dart'; import 'artisan_context.dart'; @@ -12,6 +13,7 @@ import 'artisan_input.dart'; import 'artisan_output.dart'; import 'artisan_registry.dart'; import 'command_boot.dart'; +import 'process_alive.dart'; /// Core console application + dispatcher. /// @@ -167,7 +169,12 @@ class ArtisanApplication { 'one. The app may still be building: run `artisan status` and retry, ' 'or `artisan start` again if it is not.', ); - return 1; + // A live app mid-build is the retry `start` pointed the caller at when + // it timed out with the same exit code; anything else is a failure. + final Object? pid = state['pid']; + final bool building = + state['booting'] == true && pid is int && processAlive(pid); + return building ? ArtisanCommand.exitTryAgain : 1; } final vmClient = VmServiceClient(wsUri); try { @@ -175,6 +182,11 @@ class ArtisanApplication { return await command.handle( ArtisanContext.connected(input, output, vmClient, registry: registry), ); + } on ExtensionNotRegisteredException catch (e) { + // An expected state, not a crash: the stack would only point into + // vm_service, and the line below says everything the operator can act on. + output.error(e.message); + return ArtisanCommand.exitTryAgain; } catch (e, s) { output.error('Connected command ${command.name} failed: $e'); stderr.writeln(s); diff --git a/lib/src/console/artisan_command.dart b/lib/src/console/artisan_command.dart index 7356772..9bd84dd 100644 --- a/lib/src/console/artisan_command.dart +++ b/lib/src/console/artisan_command.dart @@ -44,6 +44,12 @@ import 'command_signature.dart'; /// args, file conflicts, unreachable VM) should write to /// `ctx.output.error(...)` and return non-zero. abstract class ArtisanCommand { + /// Exit code for "not ready yet, retry": the app is still building, or has + /// not registered the extension a connected command called. Matches + /// `EX_TEMPFAIL` from `sysexits.h`, so a script can retry on it and treat + /// any other non-zero code as a real failure. + static const int exitTryAgain = 75; + /// Optional Laravel-style signature DSL. When set, [name] derives from /// it and [configure] auto-registers the declared options/flags. /// diff --git a/lib/src/vm/extension_not_registered_exception.dart b/lib/src/vm/extension_not_registered_exception.dart new file mode 100644 index 0000000..c1432df --- /dev/null +++ b/lib/src/vm/extension_not_registered_exception.dart @@ -0,0 +1,23 @@ +/// Thrown by [VmServiceClient.callServiceExtension] when the running app has +/// no handler for [method] (JSON-RPC `-32601`, method not found). +/// +/// The usual cause is timing: a connected command ran while the app was still +/// booting, before its plugin registered the extension, and the same call +/// succeeds a few seconds later. A release build (which registers no service +/// extensions) or a plugin that is not installed in the app answers the same +/// way. The dispatcher prints [message] as one line and exits with +/// [ArtisanCommand.exitTryAgain]; a command that wants to wait for the +/// extension can catch this type without importing `package:vm_service`. +final class ExtensionNotRegisteredException implements Exception { + const ExtensionNotRegisteredException(this.method); + + /// The extension that was called, e.g. `ext.dusk.snapshot`. + final String method; + + String get message => '$method is not registered in the running app yet ' + '(still booting, a release build, or the plugin is not installed). ' + 'Retry in a few seconds.'; + + @override + String toString() => message; +} diff --git a/lib/src/vm/vm_service_client.dart b/lib/src/vm/vm_service_client.dart index f9f2cfc..a17b540 100644 --- a/lib/src/vm/vm_service_client.dart +++ b/lib/src/vm/vm_service_client.dart @@ -3,6 +3,8 @@ import 'dart:async'; import 'package:vm_service/vm_service.dart' as vm; import 'package:vm_service/vm_service_io.dart'; +import 'extension_not_registered_exception.dart'; + /// Wrapper around `package:vm_service` exposing the fluttersdk-house-style /// surface that artisan connected-mode commands consume. /// @@ -68,6 +70,10 @@ class VmServiceClient { /// This makes every connected-mode handler tolerant of the standard /// `artisan_hot_restart` → next-MCP-call workflow without forcing every /// caller to invalidate its own cache. + /// + /// Throws [ExtensionNotRegisteredException] when the app has no handler + /// for [method] (JSON-RPC `-32601`), so callers can tell "not registered + /// yet" from a failed call without depending on `package:vm_service`. Future callServiceExtension( String method, { required String isolateId, @@ -75,12 +81,7 @@ class VmServiceClient { }) async { final s = _requireConnected(); try { - final resp = await s.callServiceExtension( - method, - isolateId: isolateId, - args: params, - ); - return resp.json as T; + return await _invokeExtension(s, method, isolateId, params); } on vm.RPCError catch (e) { // DWDS surfaces transient "WipError -32000 Promise was collected" // errors when a Chrome eval Promise gets GC'd before resolution @@ -91,12 +92,7 @@ class VmServiceClient { final isWipPromiseCollected = e.code == -32603 && e.message.contains('Promise was collected'); if (!isWipPromiseCollected) rethrow; - final resp = await s.callServiceExtension( - method, - isolateId: isolateId, - args: params, - ); - return resp.json as T; + return await _invokeExtension(s, method, isolateId, params); } on vm.SentinelException catch (e) { // Sentinel almost always means "isolate gone". Refresh once and try // again; if the id has not actually changed, the sentinel is @@ -108,17 +104,38 @@ class VmServiceClient { rethrow; } if (fresh == isolateId) rethrow; - final resp = await s.callServiceExtension( - method, - isolateId: fresh, - args: params, - ); + final T result = await _invokeExtension(s, method, fresh, params); // Surface the fresh id to interested callers (mcp_server caches it) // via the dedicated event stream. _lastResolvedIsolateId = fresh; _isolateRefreshController.add(fresh); _markRefreshFromException(e); + return result; + } + } + + // One extension call, with method-not-found mapped. Every attempt goes + // through here, retries included: a hot restart that minted a fresh + // isolate before its plugins registered their extensions answers the + // retry with -32601, which is the case the exception exists for. + Future _invokeExtension( + vm.VmService s, + String method, + String isolateId, + Map? params, + ) async { + try { + final resp = await s.callServiceExtension( + method, + isolateId: isolateId, + args: params, + ); return resp.json as T; + } on vm.RPCError catch (e) { + if (e.code == vm.RPCErrorKind.kMethodNotFound.code) { + throw ExtensionNotRegisteredException(method); + } + rethrow; } } diff --git a/skills/fluttersdk-artisan/SKILL.md b/skills/fluttersdk-artisan/SKILL.md index fd8c441..a801388 100644 --- a/skills/fluttersdk-artisan/SKILL.md +++ b/skills/fluttersdk-artisan/SKILL.md @@ -172,7 +172,8 @@ Branch on `status`: ``` 1. artisan_start { device: "chrome" } - Writes state.json; blocks until VM Service URI captured (90s default; CLI form takes --timeout=N). + Writes state.json; blocks until VM Service URI captured (90s default; CLI form takes --timeout=N + and exits 75 when the build is still running at the deadline). 2. artisan_status Confirm vmServiceUri present + alive: true. 3. artisan_tinker { eval: "WidgetsBinding.instance.lifecycleState.toString()" } diff --git a/skills/fluttersdk-artisan/references/mcp-tools.md b/skills/fluttersdk-artisan/references/mcp-tools.md index 11c679d..ef9dce7 100644 --- a/skills/fluttersdk-artisan/references/mcp-tools.md +++ b/skills/fluttersdk-artisan/references/mcp-tools.md @@ -155,7 +155,11 @@ another app is recorded (pid=12345). Run `artisan stop` first. ``` Other documented error messages: `Failed to capture child PIDs from start -wrapper`, `Timed out after 90s waiting for VM Service URI`, +wrapper`, `flutter run (pid ) is still building after s` (exit 75: the +session stays booting, retry a connected tool once the build finishes), +`flutter run (pid ) exited before announcing a VM Service URI` (exit 1: +read the log; the session is removed), +`Timed out after 90s waiting for VM Service URI` (CDP path), `--cdp-port expects an integer port number, got "..."`, `--cdp-port requires --device=chrome or --device=web-server`, `Flutter SDK is older than 3.30.0` (CDP path), diff --git a/skills/fluttersdk-artisan/references/state-and-recovery.md b/skills/fluttersdk-artisan/references/state-and-recovery.md index 572ac1e..31c135c 100644 --- a/skills/fluttersdk-artisan/references/state-and-recovery.md +++ b/skills/fluttersdk-artisan/references/state-and-recovery.md @@ -274,6 +274,28 @@ slow, and `artisan_logs` shows what it printed. From Bash the scrape window itself is adjustable: `./bin/fsa start -d chrome --timeout=180`. The MCP tool has no timeout parameter, so that path is CLI-only. +The CLI reaches the same state on its own when `--timeout` runs out while +flutter run is still alive (a cold macOS or iOS build): `start` prints +`flutter run (pid ) is still building after s` and exits 75, the +"retry later" code. Treat it like the interrupted start above. Exit 1 with +`exited before announcing a VM Service URI` is the real failure: read the log. + +### ` is not registered in the running app yet` + +Cause: a connected command called an `ext.*` extension the app has not +registered (JSON-RPC `-32601`). Usually the app is still booting and the +plugin registers it a moment later; a release build or a plugin missing from +the app answers the same way. The CLI prints this one line and exits 75. + +``` + + # succeeds once the extension is registered +``` + +If it never clears, the app is a release build or the plugin is not +installed in it. Plugin code can catch `ExtensionNotRegisteredException` +from `ctx.callExtension` to wait instead of failing. + ### `state.json missing vmServiceUri` Cause: a state file that records no URI and carries no `booting` marker, so diff --git a/test/commands/start_command_early_state_test.dart b/test/commands/start_command_early_state_test.dart index f9a3eb0..68f1f85 100644 --- a/test/commands/start_command_early_state_test.dart +++ b/test/commands/start_command_early_state_test.dart @@ -1,3 +1,4 @@ +import 'dart:async'; import 'dart:io'; import 'package:fluttersdk_artisan/artisan.dart'; @@ -89,4 +90,141 @@ void main() { expect(done['stdinPipe'], equals('/tmp/x.fifo')); }); }); + + // The field case: `start --device macos` on a fresh worktree, where the + // first native build (CocoaPods, SwiftPM) outlasts the 90s scrape. `start` + // used to die on the timeout's StateError and print a stack fragment, while + // the app kept building and the next connected command found its URI. + group('StartCommand when the VM Service scrape times out', () { + late Directory tempHome; + + Future<({int code, String content})> startMacos() async { + final output = BufferedOutput(); + final code = await StartCommand().handle( + ArtisanContext.bare( + MapInput({ + 'device': 'macos', + 'port': '3100', + 'dds': false, + 'profile-static': false, + 'timeout': '90', + }), + output, + ), + ); + return (code: code, content: output.content); + } + + setUp(() { + tempHome = Directory.systemTemp.createTempSync('artisan_cold_build_'); + StateFile.debugHomeOverride = tempHome.path; + StateFile.debugProjectRootOverride = Directory.current.path; + StartCommand.cdpFifoMaker = (String path) async { + File(path).writeAsStringSync(''); + }; + StartCommand.cdpProcessStarter = ( + String executable, + List arguments, { + String? workingDirectory, + ProcessStartMode? mode, + }) async => + _FakeFlutterProcess(holderPid: 4241, flutterPid: 4242); + StartCommand.cdpVmServiceScraper = (File _) async { + throw TimeoutException('Timed out after 90s'); + }; + }); + + tearDown(() async { + StateFile.debugHomeOverride = null; + StateFile.debugProjectRootOverride = null; + StartCommand.cdpFifoMaker = null; + StartCommand.cdpProcessStarter = ( + String executable, + List arguments, { + String? workingDirectory, + ProcessStartMode? mode, + }) => + Process.start( + executable, + arguments, + workingDirectory: workingDirectory, + mode: mode ?? ProcessStartMode.normal, + ); + StartCommand.cdpVmServiceScraper = null; + StartCommand.startIsAlive = processAlive; + StartCommand.cdpKillPid = Process.killPid; + if (tempHome.existsSync()) await tempHome.delete(recursive: true); + }); + + test('a build still running exits 75 with a still-building line', () async { + StartCommand.startIsAlive = (int pid) => pid == 4242; + + final result = await startMacos(); + + expect(result.code, ArtisanCommand.exitTryAgain); + expect(result.content, contains('still building after 90s')); + expect(result.content, contains('artisan status')); + expect(result.content, contains('--timeout')); + final Map? state = await StateFile.read(); + expect( + state!['booting'], + isTrue, + reason: 'the session stays recorded so a later command can heal it', + ); + expect(state['pid'], 4242); + }); + + test('a flutter run that exited during the wait fails with exit 1', + () async { + StartCommand.startIsAlive = (int _) => false; + final List killed = []; + StartCommand.cdpKillPid = (int pid, [ProcessSignal? _]) { + killed.add(pid); + return true; + }; + + final result = await startMacos(); + + expect(result.code, 1); + expect(result.content, contains('exited before')); + expect(result.content, contains('flutter-dev.log')); + expect(result.content, isNot(contains('still building'))); + // A session left behind would have `status` report a dead app as + // still booting, and the FIFO holder would outlive it for good. + expect(await StateFile.read(), isNull); + expect(killed, contains(4241), reason: 'the FIFO holder is reaped'); + expect( + File('${File(StateFile.path).parent.path}/flutter-dev.fifo') + .existsSync(), + isFalse, + ); + }); + }); +} + +class _FakeFlutterProcess implements Process { + _FakeFlutterProcess({required this.holderPid, required this.flutterPid}); + + final int holderPid; + final int flutterPid; + + @override + int get pid => 9999; + + @override + Future get exitCode => Future.value(0); + + @override + bool kill([ProcessSignal signal = ProcessSignal.sigterm]) => true; + + @override + Stream> get stdout => Stream>.value( + 'HOLDER=$holderPid\nFLUTTER=$flutterPid\n'.codeUnits, + ); + + @override + Stream> get stderr => const Stream>.empty(); + + @override + IOSink get stdin => throw UnimplementedError(); } diff --git a/test/commands/start_command_test.dart b/test/commands/start_command_test.dart index 1a9c022..20aaf7a 100644 --- a/test/commands/start_command_test.dart +++ b/test/commands/start_command_test.dart @@ -221,6 +221,7 @@ void main() { StartCommand.cdpPortProbe = StartCommand.defaultPortProbe; StartCommand.cdpKillPid = Process.killPid; StartCommand.cdpReapGrace = const Duration(seconds: 5); + StartCommand.startIsAlive = processAlive; if (tempHome.existsSync()) { await tempHome.delete(recursive: true); } @@ -1095,7 +1096,10 @@ void main() { // contains "120s" (the configured timeout) rather than "90s" (the old // hardcoded literal). StartCommand.cdpVmServiceScraper = (_) async { - throw StateError('Timed out after 120s waiting for VM Service URI'); + throw TimeoutException( + 'Timed out after 120s waiting for VM Service URI', + const Duration(seconds: 120), + ); }; final killedPids = []; @@ -1124,6 +1128,11 @@ void main() { // The scraper seam surfaces the message that uses the configured value. expect(output.content, contains('120s'), reason: 'error must report configured timeout value, not a literal'); + expect( + output.content, + isNot(contains('TimeoutException after')), + reason: 'the message names the deadline; the Duration prefix is noise', + ); }); test('live scrape loop returns the normalized URI when the log yields one', @@ -1148,11 +1157,13 @@ void main() { final log = File('${dir.path}/run.log') ..writeAsStringSync('starting up, no service uri yet\n'); + // A TimeoutException rather than a StateError: the plain branch tells a + // build that is still running from one that failed by this type. await expectLater( StartCommand().scrapeVmServiceUriForTest(log, 1), throwsA( - isA().having( - (e) => e.toString(), + isA().having( + (e) => e.message, 'message', contains('Timed out after 1s'), ), @@ -1356,6 +1367,9 @@ void main() { File(path).writeAsStringSync(''); }; + StartCommand.startIsAlive = (int _) => true; + + final output = BufferedOutput(); final ctx = ArtisanContext.bare( MapInput({ 'device': 'emulator-5554', @@ -1364,19 +1378,14 @@ void main() { 'profile-static': false, 'timeout': '1', }), - BufferedOutput(), + output, ); - await expectLater( - StartCommand().handle(ctx).timeout(const Duration(seconds: 10)), - throwsA( - isA().having( - (e) => e.toString(), - 'message', - contains('Timed out after 1s'), - ), - ), - ); + final code = + await StartCommand().handle(ctx).timeout(const Duration(seconds: 10)); + + expect(code, ArtisanCommand.exitTryAgain); + expect(output.content, contains('still building after 1s')); }); test( diff --git a/test/console/artisan_application_test.dart b/test/console/artisan_application_test.dart index 57df942..838deb2 100644 --- a/test/console/artisan_application_test.dart +++ b/test/console/artisan_application_test.dart @@ -277,9 +277,169 @@ void main() { reason: 'the record is complete now', ); }); + + group('a connected command against a booting session with no URI', () { + late Directory tempHome; + + setUp(() { + tempHome = Directory.systemTemp.createTempSync('artisan_booting_'); + StateFile.debugHomeOverride = tempHome.path; + StateFile.debugProjectRootOverride = Directory.current.path; + }); + + tearDown(() { + StateFile.debugHomeOverride = null; + StateFile.debugProjectRootOverride = null; + tempHome.deleteSync(recursive: true); + }); + + Future<({int code, String err, String out})> dispatchWithPid( + int appPid, + ) async { + await StateFile.write({ + 'pid': appPid, + 'vmServiceUri': null, + 'booting': true, + 'projectRoot': Directory.current.path, + }); + final registry = ArtisanRegistry()..register(_ConnectedCommand()); + final app = ArtisanApplication(registry: registry); + return _captureDispatch(() => app.dispatch(['connected'])); + } + + test('exits 75 while the app is still building', () async { + // `start` exits 75 on a cold build and tells the caller to retry a + // connected command; the retry has to answer in the same terms. + final result = await dispatchWithPid(pid); + + expect(result.code, 75); + expect(result.err, contains('has no vmServiceUri yet')); + }); + + test('exits 1 when the recorded app is gone', () async { + final result = await dispatchWithPid(999999); + + expect(result.code, 1); + }); + }); + + group('a connected command calling an extension', () { + late Directory tempHome; + late HttpServer server; + + // Answers `getVM` with one isolate and every other call with + // [errorCode], which is what a running app does when the extension the + // command calls has not been registered. + Future serveVm(int errorCode) async { + server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); + server.transform(WebSocketTransformer()).listen((WebSocket socket) { + socket.listen((dynamic raw) { + final Map request = + jsonDecode(raw as String) as Map; + socket.add( + jsonEncode({ + 'jsonrpc': '2.0', + 'id': request['id'], + if (request['method'] == 'getVM') + 'result': { + 'type': 'VM', + 'isolates': >[ + { + 'type': '@Isolate', + 'id': 'isolates/1', + 'name': 'main', + 'number': '1', + }, + ], + } + else + 'error': { + 'code': errorCode, + 'message': 'Method not found', + 'data': {}, + }, + }), + ); + }); + }); + await StateFile.write({ + 'pid': 4242, + 'vmServiceUri': 'ws://127.0.0.1:${server.port}/ws', + 'projectRoot': Directory.current.path, + }); + } + + setUp(() { + tempHome = Directory.systemTemp.createTempSync('artisan_ext_'); + StateFile.debugHomeOverride = tempHome.path; + StateFile.debugProjectRootOverride = Directory.current.path; + }); + + tearDown(() async { + StateFile.debugHomeOverride = null; + StateFile.debugProjectRootOverride = null; + await server.close(force: true); + tempHome.deleteSync(recursive: true); + }); + + test('reports an unregistered extension in one line and exits 75', + () async { + // The field case: a connected command run while the app is still + // booting, before it registered its extension, printed the raw + // `(-32601) Method not found` RPC error and a vm_service stack. + await serveVm(-32601); + final registry = ArtisanRegistry()..register(_ExtensionCommand()); + final app = ArtisanApplication(registry: registry); + + final result = await _captureDispatch( + () => app.dispatch(['player:state']), + ); + + expect(result.code, 75); + expect( + result.err, + contains( + 'ext.watchools.player is not registered in the running app yet', + ), + ); + expect(result.err, isNot(contains('#0')), reason: 'no stack trace'); + expect(result.err.trim().split('\n'), hasLength(1)); + }); + + test('keeps any other RPC error on the unexpected-failure path', + () async { + await serveVm(-32000); + final registry = ArtisanRegistry()..register(_ExtensionCommand()); + final app = ArtisanApplication(registry: registry); + + final result = await _captureDispatch( + () => app.dispatch(['player:state']), + ); + + expect(result.code, 3); + expect(result.err, contains('Connected command player:state failed')); + }); + }); }); } +class _ExtensionCommand extends ArtisanCommand { + @override + String get name => 'player:state'; + + @override + String get description => 'calls an app-registered extension'; + + @override + CommandBoot get boot => CommandBoot.connected; + + @override + Future handle(ArtisanContext ctx) async { + await ctx.callExtension('ext.watchools.player'); + return 0; + } +} + class _FixedExitCommand extends ArtisanCommand { _FixedExitCommand(this._name, this._exit); final String _name; diff --git a/test/vm/vm_service_client_test.dart b/test/vm/vm_service_client_test.dart index 9a8500a..4192d33 100644 --- a/test/vm/vm_service_client_test.dart +++ b/test/vm/vm_service_client_test.dart @@ -1,3 +1,6 @@ +import 'dart:convert'; +import 'dart:io'; + import 'package:fluttersdk_artisan/artisan.dart'; import 'package:test/test.dart'; @@ -90,4 +93,126 @@ void main() { await expectLater(client.disconnect(), completes); }); }); + + group('VmServiceClient.callServiceExtension (method not found)', () { + late HttpServer server; + late VmServiceClient client; + + // Answers each extension call with the next entry of [replies] (an + // `error` or a `result` member), and `getVM` with a single isolate whose + // id is [isolateId]. + Future serve( + List> replies, { + String isolateId = 'isolates/1', + }) async { + server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); + server.transform(WebSocketTransformer()).listen((WebSocket socket) { + socket.listen((dynamic raw) { + final Map request = + jsonDecode(raw as String) as Map; + socket.add( + jsonEncode({ + 'jsonrpc': '2.0', + 'id': request['id'], + if (request['method'] == 'getVM') + 'result': { + 'type': 'VM', + 'isolates': >[ + { + 'type': '@Isolate', + 'id': isolateId, + 'name': 'main', + 'number': '1', + }, + ], + } + else + ...replies.removeAt(0), + }), + ); + }); + }); + client = VmServiceClient('ws://127.0.0.1:${server.port}/ws'); + await client.connect(); + } + + const Map methodNotFound = { + 'error': { + 'code': -32601, + 'message': 'Method not found', + 'data': {}, + }, + }; + + tearDown(() async { + await client.disconnect(); + await server.close(force: true); + }); + + test('maps -32601 on the first call', () async { + await serve(>[methodNotFound]); + + await expectLater( + client.callServiceExtension( + 'ext.dusk.snapshot', + isolateId: 'isolates/1', + ), + throwsA( + isA().having( + (e) => e.method, + 'method', + 'ext.dusk.snapshot', + ), + ), + ); + }); + + test('maps -32601 on the retry after a collected promise', () async { + await serve(>[ + { + 'error': { + 'code': -32603, + 'message': 'WipError -32000 Promise was collected', + 'data': {}, + }, + }, + methodNotFound, + ]); + + await expectLater( + client.callServiceExtension( + 'ext.dusk.snapshot', + isolateId: 'isolates/1', + ), + throwsA(isA()), + ); + }); + + test('maps -32601 on the retry against a refreshed isolate', () async { + // A hot restart minted isolates/2 before its plugins registered their + // extensions: the stale id answers with a sentinel, the fresh one with + // method not found. + await serve( + >[ + { + 'result': { + 'type': 'Sentinel', + 'kind': 'Collected', + 'valueAsString': '', + }, + }, + methodNotFound, + ], + isolateId: 'isolates/2', + ); + + await expectLater( + client.callServiceExtension( + 'ext.dusk.snapshot', + isolateId: 'isolates/1', + ), + throwsA(isA()), + ); + }); + }); }