diff --git a/CHANGELOG.md b/CHANGELOG.md index 3a2f8c3..996b01a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,25 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Security + +- **The HTTP adapter no longer hands telescope a login's password or token.** It stringified request and response bodies with `toString()`, and a Dart `Map` prints as `{email: a@b.test, password: hunter2}`, which telescope's JSON masking cannot read, so a login body and a Sanctum login answer reached the agent-facing buffer in the clear. `onRequest`, `onResponse` and `onError` now mask the body with telescope's hidden request or response parameters before truncating it (`TelescopeRedaction.redactParameters` for a Dart structure, `redactBody` for a JSON string, which would otherwise stop parsing once cut at 8 KB); the masked copy is what gets recorded, and the request object the driver sends on is never touched. `MagicTelescopeIntegration.install()` also hides the header magic's `AuthInterceptor` writes the token under, read from `auth.token.header` (default `Authorization`), so a renamed header is masked too, and it does so on every call, since a telescope store reset drops the addition. Needs the telescope release that ships `TelescopeRedaction`. (`lib/src/telescope_integration.dart`) + +### Changed + +- **The floors name the releases this work needs.** `magic` moves `^0.0.22` to `^0.0.24` (`MagicPerfHooks`, the request ids, `AuthRestored.changed`, and the removal of `onRefreshUI`), `fluttersdk_dusk` `^0.0.16` to `^0.0.17` (`PerfMode` and the interaction readers), `fluttersdk_telescope` `^0.0.7` to `^0.0.9` (`TelescopeRedaction` and the record link fields) and `fluttersdk_wind` `^1.7.0` to `^1.8.0` (the size-only `MediaQuery` read the `mediaQuerySize` insight describes). Each is a real requirement: this release does not compile, or describes the wrong behaviour, below it. The README install snippet quotes the new dusk and telescope floors. (`pubspec.yaml`, `README.md`) +- **BREAKING: the perf path reads magic through `MagicPerfHooks.sink`, and `MagicController.onRefreshUI` is gone.** `MagicPerfIntegration` no longer hooks a single notify site: its session begin hook installs the sink for an attribution session only (a timing session, and an app between sessions, allocate no event and leave wind counting off), and the end hook removes it. `perfExtrasReader` returns dusk's documented key set: `controllerNotifies`, `notifyCauses`, `queryReloads`, `actions`, `events`, `casts`, `timerTicks`, `broadcasts` and `routeTransitions`. Needs the magic, dusk, telescope and wind releases that ship `MagicPerfHooks`, `PerfMode`, record links and per-type wind counters. (`lib/src/perf_integration.dart`) +- **HTTP records pair by request id.** The telescope interceptor matches each response or error to its request through `MagicRequest.id` / `MagicResponse.id` / `MagicError.id`, so two requests completing out of order keep their own URL and duration; only an answer without an id (a hand-built one; `Http.fake` installs no interceptors) falls back to the oldest request in flight that has no id either, with `attributedHeuristically: true`. A request with an id is never handed to an id-less answer, since its own answer would then find nothing to pair with and be dropped. Records carry `requestId`, `startUs` and `endUs`. (`lib/src/telescope_integration.dart`) +- **A span is linked from when it began, not when it ended.** `QueryReloaded`, `ActionRan` and `EventDispatched` arrive at span end, so resolving the link then dropped a reload that outlived its tap and gave one that ended during the next tap to that tap. `MagicPerfIntegration.interactionLink({startUs})` now accepts the zone handle when its window `[startUs, closedAtUs ?? now]` holds the span's start (closed or not), else dusk's `perfInteractionAt(startUs)` (`frame`), else `window`; an instant with no start keeps the open-handle and active-interaction rules. The `zoneInteractionId` test seam becomes `zoneInteraction` (it returns the handle's window), with a new `interactionIdAt` seam beside `activeInteractionId`. Needs the dusk release that exports `perfInteractionAt`. (`lib/src/perf_integration.dart`) +- **The `mediaQuerySize` insight describes a size-only subscription.** wind now reads `MediaQuery.sizeOf`, so a counted read rebuilds its widget on a resize or a rotation and not on a keyboard inset; the summary and next step said every MediaQuery change, which is no longer true. The metric name, threshold and firing rule are unchanged. (`lib/src/perf_insight_rules.dart`) + +- **The install guard is `!kReleaseMode`.** `MagicDevtools.installPre` / `installPost` and the per-tool blocks are documented under `!kReleaseMode` instead of `kDebugMode`, so a profile build carries dusk and telescope and a perf measurement can run on it; release still tree-shakes both, and the guard still belongs at the call site. `lib/src/dusk_integration.dart` and `lib/src/perf_integration.dart` already said so, and the rest of the package said `kDebugMode`. Apps wired under `kDebugMode` keep working in debug and simply carry no tooling in profile. (`CLAUDE.md`, `README.md`, `lib/magic_devtools.dart`, `lib/dusk.dart`, `lib/telescope.dart`, `lib/src/magic_devtools.dart`, `lib/src/telescope_integration.dart`) + +### Added + +- **Interaction links on every record.** HTTP, query, event, model and cache records, and every sink row, carry `interactionId` and `linkedBy`: `zone` when the work read an open dusk interaction off its own zone, `frame` when it ran in the frame zone and joined dusk's active interaction, `window` when neither. `MagicPerfIntegration.interactionLink()` is the one rule. Gate records are not stamped: telescope's `GateRecord` has no link fields. (`lib/src/perf_integration.dart`, `lib/src/telescope_integration.dart`) +- **`perfTimelineReader` and `perfInsightContributors` are assigned.** The timeline reader returns the sink rows (notifies, query reloads, actions, event dispatches, timer ticks, broadcasts) plus one row per telescope HTTP, query, event, model and cache record, in dusk's row schema. The contributor runs `PerfInsightRules`: wind wrapper emissions per W-widget build, `mediaQuerySize` reads per frame, parse misses on a warm surface, notify storms by cause, timer-driven notifies per second, uncached query reloads per interaction, attribute casts per frame, and HTTP requests per interaction. Every rule states its threshold in `evidence.threshold` and normalises by painted frames. (`lib/src/perf_insight_rules.dart`) + ## [0.0.7] - 2026-09-27 ### Changed diff --git a/CLAUDE.md b/CLAUDE.md index 7ae0e61..904b1e9 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -14,7 +14,8 @@ live in magic; moving them out is what lets a production app depend on magic wit driver and a runtime inspector into its resolution graph. Every consumer adds this package as a **dev_dependency**, never a dependency. -That is also why every install call is guarded by `kDebugMode` AT THE CALL SITE, in the consumer's +That is also why every install call is guarded by `!kReleaseMode` AT THE CALL SITE (debug and profile +builds carry the tools, so a perf measurement runs on a profile build), in the consumer's `main.dart`, and never inside a method here. Moving the guard inward defeats the release tree-shake and pulls both tools into the production bundle, which is the one failure this package's whole shape is arranged to prevent. @@ -110,7 +111,7 @@ throws. 3. `CHANGELOG.md` gets a bullet under `## [Unreleased]` for every behavioural or interface change. 4. Never add a dependency that would let magic core reach dusk or telescope. The direction is `magic_devtools` to the tools, never the reverse. -5. Never move a `kDebugMode` guard inside this package. +5. Never move a `!kReleaseMode` guard inside this package. ## Branching diff --git a/README.md b/README.md index 67157e8..f738b6b 100644 --- a/README.md +++ b/README.md @@ -27,24 +27,24 @@ `magic_devtools` is the Magic adapter layer for [`fluttersdk_dusk`](https://pub.dev/packages/fluttersdk_dusk) and [`fluttersdk_telescope`](https://pub.dev/packages/fluttersdk_telescope). It enriches dusk snapshots and telescope records with Magic-aware context (forms, navigation, controllers, gates, auth, broadcasting, HTTP) so an LLM agent or CI driver sees your app the way Magic sees it. -It is **debug-only**: you install and wire it under `kDebugMode`, so release builds tree-shake it entirely and it carries no runtime cost in production. This is exactly why it lives outside `magic` core; the framework keeps no dev-tooling production dependencies. +It is **dev-only**: you install and wire it under `!kReleaseMode`, so debug and profile builds carry it (a performance measurement needs a profile build) and release builds tree-shake it entirely and it carries no runtime cost in production. This is exactly why it lives outside `magic` core; the framework keeps no dev-tooling production dependencies. Four import barrels: - `package:magic_devtools/magic_devtools.dart`: `MagicDevtools` is the umbrella one-call wiring: `installPre()` boots both tool plugins (plus telescope's opt-in exception/dump watchers) before `Magic.init()`, `installPost()` wires both Magic integrations after it. - `package:magic_devtools/dusk.dart`: `MagicDuskIntegration` registers 14 Magic-aware enrichers into fluttersdk_dusk's snapshot pipeline. -- `package:magic_devtools/telescope.dart`: `MagicTelescopeIntegration` registers 5 Magic watchers and `MagicHttpFacadeAdapter` into fluttersdk_telescope. +- `package:magic_devtools/telescope.dart`: `MagicTelescopeIntegration` registers 5 Magic watchers and `MagicHttpFacadeAdapter` into fluttersdk_telescope. The adapter masks credentials before a record reaches the agent-facing buffer: `password` / `token` style keys of a request or response body and the header `auth.token.header` names (default `Authorization`) read `********`. - `package:magic_devtools/preview.dart`: `MagicPreview` hosts a dev-only component preview catalog via two plain pages (`/preview` and `/preview/:component`), tree-shaken from release builds. ## Install -`magic_devtools` and the tooling packages are imported in `lib/main.dart` (under `kDebugMode`), so they are regular `dependencies`, not `dev_dependencies`; `kDebugMode` tree-shakes them out of release builds, and because `lib/` imports them a `dev_dependencies` entry would trip the `depend_on_referenced_packages` lint. This matches how `fluttersdk_dusk` and `fluttersdk_telescope` are installed on their own. +`magic_devtools` and the tooling packages are imported in `lib/main.dart` (under `!kReleaseMode`), so they are regular `dependencies`, not `dev_dependencies`; `!kReleaseMode` tree-shakes them out of release builds, and because `lib/` imports them a `dev_dependencies` entry would trip the `depend_on_referenced_packages` lint. This matches how `fluttersdk_dusk` and `fluttersdk_telescope` are installed on their own. ```yaml dependencies: magic_devtools: ^0.0.7 - fluttersdk_dusk: ^0.0.16 # add if you use dusk - fluttersdk_telescope: ^0.0.7 # add if you use telescope + fluttersdk_dusk: ^0.0.17 # add if you use dusk + fluttersdk_telescope: ^0.0.9 # add if you use telescope ``` `magic_devtools` depends on `magic`, `fluttersdk_dusk`, and `fluttersdk_telescope` directly, so transitive resolution does not happen through `magic` itself. @@ -55,24 +55,28 @@ Both integrations are debug-only and run in `lib/main.dart`. The ordering is loa ### Both tools at once (recommended) -`MagicDevtools` collapses the four blocks below into the two halves of that ordering. Keep the `kDebugMode` guard at the call site: moving it inside the methods would make the call live in release and defeat the tree-shake. +`MagicDevtools` collapses the four blocks below into the two halves of that ordering. Keep the `!kReleaseMode` guard at the call site: moving it inside the methods would make the call live in release and defeat the tree-shake. ```dart -if (kDebugMode) MagicDevtools.installPre(); // dusk + telescope plugins + exception/dump watchers +if (!kReleaseMode) MagicDevtools.installPre(); // dusk + telescope plugins + exception/dump watchers await Magic.init(configFactories: [...]); -if (kDebugMode) MagicDevtools.installPost(); // MagicTelescopeIntegration + MagicDuskIntegration +if (!kReleaseMode) MagicDevtools.installPost(); // MagicTelescopeIntegration + MagicDuskIntegration ``` Reach for the individual barrels below when you need only one tool, or a non-standard telescope watcher set (register extra watchers with `TelescopePlugin.registerWatcher` after `installPre`). +### Performance sessions + +`installPre()` also installs `MagicPerfIntegration`, the data path behind dusk's `perf_begin` / `perf_end` / `perf_trace`. During an attribution session it counts magic's runtime activity through `MagicPerfHooks.sink` and wind's build, wrapper and inherited-read counters, stamps every telescope record with the dusk interaction it belongs to (`linkedBy: zone | frame | window`), and contributes wind and magic insights (`PerfInsightRules`) whose thresholds each insight states in `evidence.threshold`. A timing session touches neither counter. + ### Dusk ```dart -if (kDebugMode) { +if (!kReleaseMode) { DuskPlugin.install(); } await Magic.init(configFactories: [...]); -if (kDebugMode) { +if (!kReleaseMode) { MagicDuskIntegration.install(); } ``` @@ -80,11 +84,11 @@ if (kDebugMode) { ### Telescope ```dart -if (kDebugMode) { +if (!kReleaseMode) { TelescopePlugin.install(); } await Magic.init(configFactories: [...]); -if (kDebugMode) { +if (!kReleaseMode) { MagicTelescopeIntegration.install(); } ``` diff --git a/lib/dusk.dart b/lib/dusk.dart index f6d6ed6..0b4095b 100644 --- a/lib/dusk.dart +++ b/lib/dusk.dart @@ -13,11 +13,11 @@ /// live during Magic boot: /// /// ```dart -/// if (kDebugMode) { +/// if (!kReleaseMode) { /// DuskPlugin.install(); /// } /// await Magic.init(configFactories: [...]); -/// if (kDebugMode) { +/// if (!kReleaseMode) { /// MagicDuskIntegration.install(); /// } /// ``` diff --git a/lib/magic_devtools.dart b/lib/magic_devtools.dart index 219226c..195b2e4 100644 --- a/lib/magic_devtools.dart +++ b/lib/magic_devtools.dart @@ -2,7 +2,7 @@ /// /// Exposes [MagicDevtools], the one-call `installPre` / `installPost` wiring /// for fluttersdk_dusk and fluttersdk_telescope plus their Magic -/// integrations, installed around [Magic.init] under `kDebugMode`. +/// integrations, installed around [Magic.init] under `!kReleaseMode`. /// /// See the finer-grained `dusk.dart`, `telescope.dart`, and `preview.dart` /// barrels when you need direct access to a single integration, a diff --git a/lib/src/dusk_integration.dart b/lib/src/dusk_integration.dart index 6dd8b09..f60c85a 100644 --- a/lib/src/dusk_integration.dart +++ b/lib/src/dusk_integration.dart @@ -8,9 +8,10 @@ import 'package:magic/magic.dart'; /// Glues magic's primitives (MagicForm, MagicRouter, Gate, Auth, Echo) into /// the fluttersdk_dusk snapshot pipeline. /// -/// Host integration (debug-only): +/// Host integration (the consumer gates with `!kReleaseMode`, so debug and +/// profile both carry it and release tree-shakes it): /// ```dart -/// if (kDebugMode) { +/// if (!kReleaseMode) { /// DuskPlugin.install(); /// MagicDuskIntegration.install(); /// } diff --git a/lib/src/magic_devtools.dart b/lib/src/magic_devtools.dart index 3dc8ab3..711b0bc 100644 --- a/lib/src/magic_devtools.dart +++ b/lib/src/magic_devtools.dart @@ -5,6 +5,7 @@ import 'dusk_integration.dart'; import 'perf_integration.dart'; import 'telescope_integration.dart'; +export 'perf_insight_rules.dart'; export 'perf_integration.dart'; /// One-call wiring for the Magic dev-tooling bundle: fluttersdk_dusk + @@ -25,7 +26,8 @@ export 'perf_integration.dart'; /// snapshot enrichers resolve dependencies through the IoC container /// (`Magic.find` / `Magic.bound`). /// -/// Keep both calls inside a `kDebugMode` guard AT THE CALL SITE. Do not move +/// Keep both calls inside a `!kReleaseMode` guard AT THE CALL SITE (debug and +/// profile builds carry the tools; release tree-shakes them). Do not move /// the guard inside these methods: a live (unguarded) call defeats the /// release tree-shake and pulls dusk + telescope into the production bundle, /// which is the whole reason this wiring lives outside `magic` core. @@ -34,11 +36,11 @@ export 'perf_integration.dart'; /// void main() async { /// WidgetsFlutterBinding.ensureInitialized(); /// -/// if (kDebugMode) MagicDevtools.installPre(); +/// if (!kReleaseMode) MagicDevtools.installPre(); /// /// await Magic.init(configFactories: [...]); /// -/// if (kDebugMode) MagicDevtools.installPost(); +/// if (!kReleaseMode) MagicDevtools.installPost(); /// /// runApp(const MyApp()); /// } diff --git a/lib/src/perf_insight_rules.dart b/lib/src/perf_insight_rules.dart new file mode 100644 index 0000000..d716f7b --- /dev/null +++ b/lib/src/perf_insight_rules.dart @@ -0,0 +1,510 @@ +/// The wind and magic insight rules `ext.dusk.perf_end` runs through dusk's +/// `perfInsightContributors` seam. +/// +/// They live here, not in dusk, because judging them needs to know what a +/// wind wrapper or a magic notify cause MEANS, and dusk may not import either +/// package. Every rule states the threshold it fired on in +/// `evidence.threshold` and normalises by painted frames (the report's +/// `coverage.framesSummarized`), the one denominator two sessions of +/// different length share. A rule that cannot compute its denominator stays +/// silent rather than guessing. +library; + +/// Everything the rules read beyond the report dusk hands a contributor. +/// +/// The report carries each counter family cut to its ranked head, so a rule +/// reading it would judge a truncated sum; these are the same families UNCUT, +/// plus the per-interaction joins the report does not carry at all. +final class PerfRuleInputs { + const PerfRuleInputs({ + required this.extras, + required this.wind, + required this.notifiesByCause, + required this.uncachedReloads, + required this.httpByInteraction, + }); + + /// `perfExtrasReader()` as read for this report. + final Map extras; + + /// wind's `WindPerfResolver.stats()`, or null when no resolver is + /// registered. + final Map? wind; + + /// Notify cause name to controller type to notifies. + final Map> notifiesByCause; + + /// Interaction id to model type to reloads that issued their own request + /// rather than joining one in flight. + final Map> uncachedReloads; + + /// Interaction id to the `METHOD url` of every request it sent, in order. + final Map> httpByInteraction; +} + +/// The rules. Stateless; [evaluate] is the contributor. +abstract final class PerfInsightRules { + /// A wrapper type is reported once it is emitted this many times per + /// W-widget build... + static const double wrapperMinPerWidgetBuild = 0.5; + + /// ...and this many times per painted frame, so a screen of three buttons + /// does not report its three MouseRegions. + static const double wrapperMinPerFrame = 20; + + /// `MediaQuery` size reads per painted frame. + static const double mediaQueryMinPerFrame = 10; + + /// Parse misses a warm surface may take before the rate is judged at all. + static const int parseMinMisses = 20; + + /// Share of parses that missed the cache. + static const double parseMinMissRate = 0.1; + + /// Notifies of one cause per painted frame. Past one, the frame coalesced + /// the rest: work done for no pixel. + static const double notifyMinPerFrame = 2; + + /// Timer-driven notifies per second of session. A one-second countdown is + /// one; a poll or debounce firing faster is the storm. + static const double timerNotifyMinPerSecond = 4; + + /// Reloads of one model type inside one interaction that each issued their + /// own request. The first is the fetch; a second is a refetch. + static const int uncachedReloadsMaxPerInteraction = 1; + + /// Computed attribute casts per painted frame. + static const double castMinPerFrame = 50; + + /// Requests one interaction may send. + static const int httpMaxPerInteraction = 4; + + /// Times one interaction may send the same request. + static const int httpMaxSameRequestPerInteraction = 1; + + /// Why a wrapper is emitted, for the wrappers a W-widget adds on its own. + static const Map _wrapperCauses = { + 'MouseRegion': + 'WAnchor emits a MouseRegion on every build (WButton wraps ' + 'one), and WDiv adds another for any cursor-* class', + 'Focus': 'WAnchor emits a Focus on every build (WButton wraps one)', + 'WindAnchorStateProvider': + 'WAnchor emits its state provider on every ' + 'build (WButton wraps one)', + 'Semantics': + 'WAnchor, WCheckbox, WRadio, WSwitch and WInput each emit a ' + 'Semantics node', + 'WindFullHeightBox': 'WDiv emits one for every h-full class', + }; + + /// Runs every rule against [report] and returns the insights that fired, in + /// the shape dusk's contributor seam takes. + /// + /// Nothing fires on a timing report: it carries no counters, and its + /// milliseconds are the ones a rule must not tax. + static List> evaluate( + Map report, + PerfRuleInputs inputs, + ) { + final int painted = _int(_map(report['coverage'])['framesSummarized']); + if (report['mode'] != 'attribution' || painted == 0) { + return const >[]; + } + final Map summary = _map(report['summary']); + final Object? routes = summary['routeTransitions']; + final Object? durationMs = summary['durationMs']; + + return ?>[ + _wrapperEmissions(inputs.wind, painted), + _mediaQueryReads(inputs.wind, painted), + _warmParseMisses( + inputs.wind, + painted, + navigated: routes is List && routes.isNotEmpty, + ), + _notifyStorm(inputs.notifiesByCause, painted), + _timerNotifies( + inputs.notifiesByCause, + painted, + durationMs is num ? durationMs.toDouble() : null, + ), + _uncachedReloads(inputs.uncachedReloads, painted), + _casts(inputs.extras, painted), + _httpPerInteraction(inputs.httpByInteraction, painted), + ].whereType>().toList(); + } + + // ------------------------------------------------------------------------- + // wind + // ------------------------------------------------------------------------- + + static Map? _wrapperEmissions( + Map? wind, + int painted, + ) { + final int builds = _sum(_counts(wind?['widgetBuilds'])); + if (builds == 0) return null; + + final List> qualifying = + _ranked(_counts(wind?['wrapperEmissions'])) + .where( + (MapEntry e) => + e.value / builds >= wrapperMinPerWidgetBuild && + e.value / painted >= wrapperMinPerFrame, + ) + .toList(); + if (qualifying.isEmpty) return null; + + final MapEntry top = qualifying.first; + final double perBuild = _round(top.value / builds); + final String cause = + _wrapperCauses[top.key] ?? + 'find the W-widget whose className asks for it'; + + return _insight( + title: '${top.key} emitted $perBuild times per W-widget build', + summary: + 'wind emitted ${top.value} ${top.key} wrappers against $builds ' + 'W-widget builds over $painted painted frames. Each is an element ' + 'built, laid out and (for MouseRegion) hit-tested on every pointer ' + 'move. Cause: $cause.', + metric: 'wind.wrapperEmissions.${top.key}', + value: top.value, + painted: painted, + threshold: { + 'minPerWidgetBuild': wrapperMinPerWidgetBuild, + 'minPerFrame': wrapperMinPerFrame, + }, + nextStep: + 'Find the repeated rows that emit ${top.key} ($cause) and ' + 'whether each row needs it; widgetBuilds names the W-widget types.', + detail: { + 'wrappers': _rows(qualifying, painted), + 'widgetBuilds': _rows(_ranked(_counts(wind?['widgetBuilds'])), painted), + }, + ); + } + + static Map? _mediaQueryReads( + Map? wind, + int painted, + ) { + final int reads = _counts(wind?['inheritedReads'])['mediaQuerySize'] ?? 0; + if (reads / painted < mediaQueryMinPerFrame) return null; + + return _insight( + title: '${_round(reads / painted)} MediaQuery size reads per frame', + summary: + 'wind read MediaQuery size $reads times over $painted painted ' + 'frames. WDiv reads it for every h-full box and for a grid laid out ' + 'under unbounded width, through MediaQuery.sizeOf, which subscribes ' + 'the widget to the size aspect only: a resize or a rotation ' + 'rebuilds each one, not a keyboard inset.', + metric: 'wind.inheritedReads.mediaQuerySize', + value: reads, + painted: painted, + threshold: {'minPerFrame': mediaQueryMinPerFrame}, + nextStep: + 'Find the repeated h-full boxes (or unbounded grids) and give ' + 'them a bounded parent or a fixed height, so a resize or a ' + 'rotation stops rebuilding each of them.', + ); + } + + static Map? _warmParseMisses( + Map? wind, + int painted, { + required bool navigated, + }) { + if (navigated || wind == null) return null; + final int misses = _int(wind['cacheMisses']); + final int parses = misses + _int(wind['cacheHits']); + if (misses < parseMinMisses || misses / parses < parseMinMissRate) { + return null; + } + final double rate = _round(misses / parses); + + return _insight( + title: 'wind missed its parse cache on $misses of $parses parses', + summary: + 'No route was pushed during the session, so the surface was ' + 'already built, yet ${(rate * 100).round()}% of className parses ' + 'missed the style cache. On a warm surface a miss means a className ' + 'string that changes between builds (an interpolated value, a ' + 'per-row color), so it is parsed again every time.', + metric: 'wind.cacheMisses', + value: misses, + painted: painted, + threshold: { + 'minMisses': parseMinMisses, + 'minMissRate': parseMinMissRate, + 'requiresNoRouteTransition': true, + }, + nextStep: + 'Find the className built by interpolation in the rebuilt rows ' + 'and move the varying part to a fixed token set.', + ); + } + + // ------------------------------------------------------------------------- + // magic + // ------------------------------------------------------------------------- + + static Map? _notifyStorm( + Map> byCause, + int painted, + ) { + // Timer ticks are judged per second below; counted here too they would + // report the same notifies twice under two thresholds. + final List> causes = _ranked({ + for (final MapEntry> e in byCause.entries) + if (e.key != 'timerTick') e.key: _sum(e.value), + }); + if (causes.isEmpty || causes.first.value / painted < notifyMinPerFrame) { + return null; + } + final MapEntry top = causes.first; + final List> controllers = _ranked(byCause[top.key]!); + + return _insight( + title: + '${controllers.first.key} notified ' + '${_round(top.value / painted)} times per frame (${top.key})', + summary: + '${top.value} ${top.key} notifies over $painted painted frames. ' + 'A frame coalesces every notify before it, so all but one per frame ' + 'rebuilt listeners for no new pixel.', + metric: 'magic.notifyCauses.${top.key}', + value: top.value, + painted: painted, + threshold: {'minPerFrame': notifyMinPerFrame}, + nextStep: + 'Batch the state changes in ${controllers.first.key} behind ' + 'one setState, or narrow what listens to it.', + detail: {'controllers': _rows(controllers, painted)}, + ); + } + + static Map? _timerNotifies( + Map> byCause, + int painted, + double? durationMs, + ) { + final Map ticks = + byCause['timerTick'] ?? const {}; + final int total = _sum(ticks); + if (durationMs == null || durationMs <= 0 || total == 0) return null; + final double perSecond = total / (durationMs / 1000); + if (perSecond < timerNotifyMinPerSecond) return null; + final List> controllers = _ranked(ticks); + + return _insight( + title: + '${controllers.first.key} notified ${_round(perSecond)} times ' + 'per second from timers', + summary: + '$total notifies ran inside a Countdown, Debouncer or Poll ' + 'tick over ${_round(durationMs / 1000)}s, each rebuilding every ' + 'listener of the controller whether or not what it shows changed.', + metric: 'magic.notifyCauses.timerTick', + value: total, + painted: painted, + threshold: {'minPerSecond': timerNotifyMinPerSecond}, + nextStep: + 'Slow the timer in ${controllers.first.key}, or notify only ' + 'when the displayed value changes.', + detail: { + 'perSecond': _round(perSecond), + 'controllers': _rows(controllers, painted), + }, + ); + } + + static Map? _uncachedReloads( + Map> byInteraction, + int painted, + ) { + ({String interaction, String type, int count})? worst; + int total = 0; + for (final MapEntry> i in byInteraction.entries) { + for (final MapEntry t in i.value.entries) { + total += t.value; + if (worst == null || t.value > worst.count) { + worst = (interaction: i.key, type: t.key, count: t.value); + } + } + } + if (worst == null || worst.count <= uncachedReloadsMaxPerInteraction) { + return null; + } + + return _insight( + title: + '${worst.type} reloaded ${worst.count} times in interaction ' + '${worst.interaction}', + summary: + 'Interaction ${worst.interaction} reloaded ${worst.type} ' + '${worst.count} times, each issuing its own request instead of ' + 'joining the first one in flight.', + metric: 'magic.queryReloads.uncached', + value: worst.count, + perFrameValue: total, + painted: painted, + threshold: { + 'maxUncachedPerInteraction': uncachedReloadsMaxPerInteraction, + }, + nextStep: + 'Mount-time reads should call ensureFresh(), which joins a ' + 'load in flight; find which screen calls reload() on mount.', + detail: {'byInteraction': byInteraction}, + ); + } + + static Map? _casts( + Map extras, + int painted, + ) { + final Map casts = _counts(extras['casts']); + final int total = _sum(casts); + if (total / painted < castMinPerFrame) return null; + final List> ranked = _ranked(casts); + + return _insight( + title: + '${_round(total / painted)} attribute casts per frame, mostly ' + '${ranked.first.key}', + summary: + 'Model.getAttribute computed $total casts over $painted painted ' + 'frames. A cast is recomputed on every read that is not memoised, ' + 'so a row reading a datetime or json attribute in build pays it on ' + 'every rebuild.', + metric: 'magic.casts', + value: total, + painted: painted, + threshold: {'minPerFrame': castMinPerFrame}, + nextStep: + 'Read the ${ranked.first.key} attribute once per build into a ' + 'local, or out of build altogether.', + detail: {'casts': _rows(ranked, painted)}, + ); + } + + static Map? _httpPerInteraction( + Map> byInteraction, + int painted, + ) { + ({String interaction, int count, String? repeated, int repeats})? worst; + int total = 0; + for (final MapEntry> i in byInteraction.entries) { + total += i.value.length; + final Map same = {}; + for (final String request in i.value) { + same.update(request, (int n) => n + 1, ifAbsent: () => 1); + } + final MapEntry most = _ranked(same).first; + final bool over = + i.value.length > httpMaxPerInteraction || + most.value > httpMaxSameRequestPerInteraction; + if (over && (worst == null || i.value.length > worst.count)) { + worst = ( + interaction: i.key, + count: i.value.length, + repeated: most.value > 1 ? most.key : null, + repeats: most.value, + ); + } + } + if (worst == null) return null; + + return _insight( + title: + 'Interaction ${worst.interaction} sent ${worst.count} requests' + '${worst.repeated == null ? '' : ', ${worst.repeated} ' + '${worst.repeats} times'}', + summary: + 'One interaction sent ${worst.count} HTTP requests. Every one ' + 'is a round trip the screen may wait on, and the same request sent ' + 'twice is a fetch nothing reused.', + metric: 'magic.httpPerInteraction', + value: worst.count, + perFrameValue: total, + painted: painted, + threshold: { + 'maxPerInteraction': httpMaxPerInteraction, + 'maxSameRequestPerInteraction': httpMaxSameRequestPerInteraction, + }, + nextStep: + 'Export the trace (dusk:perf_trace) and read the http track ' + 'under ${worst.interaction}: which screen sends each request, and ' + 'which could share one.', + detail: {'requests': byInteraction[worst.interaction]}, + ); + } + + // ------------------------------------------------------------------------- + // Helpers + // ------------------------------------------------------------------------- + + /// One insight in the contributor shape. [perFrameValue] is the count the + /// per-frame figure divides when it is not [value] itself (a worst case + /// reported against a session total). + static Map _insight({ + required String title, + required String summary, + required String metric, + required int value, + required int painted, + required Map threshold, + required String nextStep, + int? perFrameValue, + Map? detail, + }) => { + 'severity': 'warn', + 'title': title, + 'summary': summary, + 'evidence': { + 'metric': metric, + 'value': value, + 'perFrame': _round((perFrameValue ?? value) / painted), + 'threshold': threshold, + }, + 'nextStep': nextStep, + 'detail': ?detail, + }; + + static List> _rows( + List> ranked, + int painted, + ) => ranked + .map( + (MapEntry e) => [ + e.key, + e.value, + _round(e.value / painted), + ], + ) + .toList(); + + static List> _ranked(Map counts) => + counts.entries.toList()..sort( + (MapEntry a, MapEntry b) => b.value != a.value + ? b.value.compareTo(a.value) + : a.key.compareTo(b.key), + ); + + static Map _counts(Object? raw) => { + if (raw is Map) + for (final MapEntry e in raw.entries) + if (e.value is int) '${e.key}': e.value! as int, + }; + + static Map _map(Object? raw) => + raw is Map ? raw : const {}; + + static int _sum(Map counts) => + counts.values.fold(0, (int sum, int n) => sum + n); + + static int _int(Object? value) => value is num ? value.toInt() : 0; + + static double _round(num value) => (value * 100).round() / 100; +} diff --git a/lib/src/perf_integration.dart b/lib/src/perf_integration.dart index 1be2090..6089f7b 100644 --- a/lib/src/perf_integration.dart +++ b/lib/src/perf_integration.dart @@ -1,16 +1,26 @@ +import 'dart:async'; import 'dart:collection'; +import 'package:flutter/foundation.dart' show FlutterTimeline; import 'package:flutter/scheduler.dart'; import 'package:flutter/widgets.dart'; import 'package:fluttersdk_dusk/dusk.dart' show + PerfInteraction, + PerfMode, + activeInteraction, framePerfReader, perfExtrasReader, + perfInsightContributors, + perfInteractionAt, perfSessionBeginHook, - perfSessionEndHook; + perfSessionEndHook, + perfTimelineReader; import 'package:fluttersdk_telescope/telescope.dart'; import 'package:magic/magic.dart'; +import 'perf_insight_rules.dart'; + /// dusk's own no-op defaults, captured the first time [MagicPerfIntegration] /// is about to overwrite them. /// @@ -27,16 +37,20 @@ import 'package:magic/magic.dart'; /// before replacing it. Map Function()? _duskFramePerfDefault; Map Function()? _duskPerfExtrasDefault; -void Function()? _duskSessionBeginDefault; +void Function(PerfMode mode)? _duskSessionBeginDefault; void Function()? _duskSessionEndDefault; +List> Function()? _duskTimelineDefault; -/// Assembles the whole performance-diagnostic data path: magic's controller and -/// route activity, wind's aggregate counters, telescope's frame buffer, and the -/// four pointers `fluttersdk_dusk` reads them all through. +/// Assembles the whole performance-diagnostic data path: magic's runtime +/// activity through `MagicPerfHooks`, wind's aggregate counters, telescope's +/// frame and record buffers, the wind and magic insight rules, and the dusk +/// pointers that read them all. /// -/// Host integration (debug-only, and BEFORE `Magic.init()`; see [install]): +/// Host integration (the consumer gates with `!kReleaseMode`, so debug and +/// profile both carry it and release tree-shakes it; BEFORE `Magic.init()`, +/// see [install]): /// ```dart -/// if (kDebugMode) MagicDevtools.installPre(); +/// if (!kReleaseMode) MagicDevtools.installPre(); /// ``` /// /// This package is the only place in the ecosystem where dusk, telescope, wind @@ -69,12 +83,17 @@ class MagicPerfIntegration { /// been read (`magic/lib/src/routing/magic_router.dart:158`). That throw is /// deliberately not caught. A swallowed one would leave the report with no /// route transitions and nothing to explain their absence. + /// + /// `MagicPerfHooks.sink` is NOT assigned here: the session's begin hook + /// installs it for an attribution session only and the end hook removes it, + /// so an app between sessions, and a timing session, pay magic's single + /// null check per site and allocate no event. static void install() { if (_installed) return; // 1. Registered once and tracked separately, because the guard below is // armed at the END rather than here. Arming it early would make a retry - // after a throw in steps 2 to 4 a silent no-op, which is the failure + // after a throw in steps 2 to 3 a silent no-op, which is the failure // this class exists to prevent; arming it late without this flag would // register a second observer on that retry. if (!_observerRegistered) { @@ -82,12 +101,7 @@ class MagicPerfIntegration { _observerRegistered = true; } - // 2. magic: one hook on the single notifyListeners() call site in - // MagicController, counted per controller runtime type so the report can - // name which controller is rebuilding the screen. - MagicController.onRefreshUI = _recordNotify; - - // 3. wind and telescope: the two producers. Installing wind's resolver + // 2. wind and telescope: the two producers. Installing wind's resolver // costs nothing on its own; counting stays off until a session's begin // hook enables it. Wind.installPerfResolver(); @@ -95,7 +109,7 @@ class MagicPerfIntegration { TelescopePlugin.registerWatcher(watcher); _watcher = watcher; - // 4. The four dusk pointers. Each returns exactly the key set pinned in + // 3. The dusk pointers. Each returns exactly the key set pinned in // `dusk/lib/src/utils/perf_readers.dart`; the consumer is in another // repository, so a renamed key is invisible until a driven run. // @@ -105,35 +119,43 @@ class MagicPerfIntegration { _duskPerfExtrasDefault ??= perfExtrasReader; _duskSessionBeginDefault ??= perfSessionBeginHook; _duskSessionEndDefault ??= perfSessionEndHook; + _duskTimelineDefault ??= perfTimelineReader; framePerfReader = () => { 'frames': TelescopeStore.recentFramePerf() .map>((FramePerfRecord r) => r.toJson()) .toList(), 'livenessCounter': FramePerfWatcher.livenessCounter, }; - perfExtrasReader = () => { - 'controllerNotifies': controllerNotifyCounts, - 'routeTransitions': routeTransitions, - }; - perfSessionBeginHook = () { + perfExtrasReader = () => _session.extras(routeTransitions); + perfTimelineReader = _timelineRows; + perfSessionBeginHook = (PerfMode mode) { + final bool attribution = mode == PerfMode.attribution; WindPerfCounters.reset(); - WindPerfCounters.enabled = true; + // Timing mode must not pay for counters: wind's sit on WindParser.parse + // and magic's allocate an event per notify, both inside the very + // durations a timing session exists to report. + WindPerfCounters.enabled = attribution; + MagicPerfHooks.sink = attribution ? _session.record : null; // clearFramePerf(), never clear(): the latter wipes the HTTP, log and // exception buffers a developer may be reading alongside the session, // and resetForTesting() is @visibleForTesting and would fail analysis. TelescopeStore.clearFramePerf(); // The magic-side counters are session-scoped for the same reason wind's // are: without this, every session reports the sum of all previous ones. - _controllerNotifies.clear(); + _session.open(FlutterTimeline.now); _routeTransitions.clear(); }; perfSessionEndHook = () { // Counting off, totals intact: `perf_end` reads them to build its // report, and `WindParser.parse` is too hot to leave instrumented. WindPerfCounters.enabled = false; + MagicPerfHooks.sink = null; }; + if (!perfInsightContributors.contains(_contributeInsights)) { + perfInsightContributors.add(_contributeInsights); + } - // 5. Last, so a throw anywhere above leaves the door open for a retry. + // 4. Last, so a throw anywhere above leaves the door open for a retry. _installed = true; } @@ -141,10 +163,92 @@ class MagicPerfIntegration { @visibleForTesting static bool get isInstalled => _installed; + /// Which interaction the calling code belongs to, and how that was + /// established, in dusk's order: + /// + /// 1. `zone`: an interaction read off `Zone.current`, for work a gesture + /// started (its callbacks, and the timers, microtasks and streams they + /// created). + /// 2. `frame`: an interaction joined by time, for work in the binding's + /// frame zone that no zone reaches (a build, an `initState` refetch). + /// 3. `window`: no interaction; the work belongs to the session window only. + /// + /// Every telescope record and every sink row this package writes is stamped + /// with it, so one rule decides all of them. + /// + /// [startUs] is when the work BEGAN, for a span that is only reported when + /// it ends (a query reload, an action, an event dispatch). Resolving such a + /// span at its end asks the wrong question: a reload that outlives the tap + /// that started it would find the tap closed and drop it, and one that ends + /// during the next tap would take that tap's zone. With it, the zone handle + /// is accepted when its window `[startUs, closedAtUs ?? now]` holds the + /// start, closed or not, and otherwise dusk's `perfInteractionAt` names the + /// interaction whose window does (`frame`). The active slot is not consulted: + /// it answers for now, not for [startUs]. + /// + /// With no [startUs] the work is an instant, and the rules are the older + /// ones: only an OPEN zone handle counts, then the active interaction. + static ({String? interactionId, String linkedBy}) interactionLink({ + int? startUs, + }) { + final ({String id, int startUs, int? closedAtUs})? zoned = zoneInteraction( + Zone.current[PerfInteraction.zoneKey], + ); + if (zoned != null && _holds(zoned, startUs)) { + return (interactionId: zoned.id, linkedBy: 'zone'); + } + + final String? joined = startUs == null + ? activeInteractionId() + : interactionIdAt(startUs); + if (joined != null) return (interactionId: joined, linkedBy: 'frame'); + + return (interactionId: null, linkedBy: 'window'); + } + + /// Whether [handle] owns the work that began at [startUs]. + /// + /// A closed handle is absent for an instant: timers and stream subscriptions + /// created in the zone keep the handle forever, and without the check every + /// later message on a socket opened during a tap would be attributed to that + /// tap. A span that began inside the window is different, since it really + /// did start there. + static bool _holds( + ({String id, int startUs, int? closedAtUs}) handle, + int? startUs, + ) { + if (startUs == null) return handle.closedAtUs == null; + + return startUs >= handle.startUs && + startUs <= (handle.closedAtUs ?? FlutterTimeline.now); + } + + /// The window of an interaction held as a zone value, or null when the value + /// is not one. + /// + /// Replaceable only because dusk's `PerfInteraction` has a private + /// constructor: a host test cannot open a real one without driving a perf + /// session over the VM Service, so it substitutes what counts as a handle. + @visibleForTesting + static ({String id, int startUs, int? closedAtUs})? Function( + Object? zoneValue, + ) + zoneInteraction = _duskZoneInteraction; + + /// The id of the interaction whose window holds [us], or null. Replaceable + /// for the reason given on [zoneInteraction]. + @visibleForTesting + static String? Function(int us) interactionIdAt = _duskInteractionIdAt; + + /// The id of dusk's active interaction, or null. Replaceable for the reason + /// given on [zoneInteraction]. + @visibleForTesting + static String? Function() activeInteractionId = _duskActiveInteractionId; + /// How many times each controller type has called `refreshUI()` since the - /// last session began, keyed by `runtimeType.toString()`. + /// last attribution session began, keyed by `runtimeType.toString()`. static Map get controllerNotifyCounts => - Map.of(_controllerNotifies); + Map.of(_session.controllerNotifies); /// Route pushes observed since the last session began, oldest first. Each /// entry carries `route` (the page name magic stamps on its routes, which is @@ -153,9 +257,10 @@ class MagicPerfIntegration { static List> get routeTransitions => _routeTransitions.toList(); - /// Test-only reset. Drops the idempotency guard, clears the magic-side - /// counters, uninstalls the frame watcher, and restores all four dusk - /// pointers to their no-op defaults so a later test asserting the + /// Test-only reset. Drops the idempotency guard, clears the session state, + /// removes the sink and this package's insight contributor, uninstalls the + /// frame watcher, restores the interaction sources, and restores every dusk + /// pointer to its no-op default so a later test asserting the /// missing-integration behaviour does not see a leaked binding. /// /// Also forces wind's counting off: a test that ran the begin hook would @@ -169,17 +274,21 @@ class MagicPerfIntegration { static void resetForTesting() { _installed = false; _observerRegistered = false; - _controllerNotifies.clear(); + _session.open(null); _routeTransitions.clear(); - MagicController.onRefreshUI = null; + MagicPerfHooks.sink = null; + perfInsightContributors.remove(_contributeInsights); + zoneInteraction = _duskZoneInteraction; + interactionIdAt = _duskInteractionIdAt; + activeInteractionId = _duskActiveInteractionId; _watcher?.uninstall(); _watcher = null; WindPerfCounters.enabled = false; // Restored from the values dusk itself declared rather than hand-written // here. Re-typing them would let this package and its tests agree on a key // set that had drifted from dusk's, and the assertions would keep passing - // while production drifted with them. See the four fields at the top of - // this file for why they are captured on the first install and not at load. + // while production drifted with them. See the fields at the top of this + // file for why they are captured on the first install and not at load. // // Null only when install() never ran, in which case the pointers are // already at dusk's defaults and there is nothing to put back. @@ -188,17 +297,116 @@ class MagicPerfIntegration { perfExtrasReader = _duskPerfExtrasDefault!; perfSessionBeginHook = _duskSessionBeginDefault!; perfSessionEndHook = _duskSessionEndDefault!; + perfTimelineReader = _duskTimelineDefault!; } } - static void _recordNotify(MagicController controller) { - _controllerNotifies.update( - controller.runtimeType.toString(), - (int count) => count + 1, - ifAbsent: () => 1, - ); + static ({String id, int startUs, int? closedAtUs})? _duskZoneInteraction( + Object? zoneValue, + ) => zoneValue is PerfInteraction + ? ( + id: zoneValue.id, + startUs: zoneValue.startUs, + closedAtUs: zoneValue.closedAtUs, + ) + : null; + + static String? _duskInteractionIdAt(int us) => perfInteractionAt(us)?.id; + + static String? _duskActiveInteractionId() => activeInteraction()?.id; + + /// The contributor dusk's insight engine calls with the report built so + /// far. Reads the uncut session state the report only carries the head of. + static List> _contributeInsights( + Map report, + ) => PerfInsightRules.evaluate( + report, + PerfRuleInputs( + extras: _session.extras(routeTransitions), + wind: const WindPerfResolverImpl().stats(), + notifiesByCause: _session.notifiesByCause, + uncachedReloads: _session.uncachedReloads, + httpByInteraction: _httpByInteraction(), + ), + ); + + /// `METHOD path` of every request an interaction sent since the session + /// opened, per interaction id. Requests linked to no interaction are left + /// out: "per interaction" means nothing for them. + static Map> _httpByInteraction() { + final int since = _session.startUs ?? 0; + final Map> out = >{}; + for (final HttpRequestRecord r in TelescopeStore.recentHttp()) { + final String? id = r.interactionId; + if (id == null || (r.startUs ?? r.atUs) < since) continue; + out.putIfAbsent(id, () => []).add('${r.method} ${_path(r.url)}'); + } + return out; } + /// perfTimelineReader rows: the sink rows this package aggregated, then one + /// row per telescope record that has a time. dusk keeps the ones inside the + /// session window, so the whole buffer is returned. + static List> _timelineRows() => >[ + ..._session.rows, + for (final HttpRequestRecord r in TelescopeStore.recentHttp()) + _row( + kind: 'span', + track: 'http', + name: '${r.method} ${_path(r.url)}', + startUs: r.startUs ?? r.atUs - r.durationMs * 1000, + endUs: r.endUs ?? r.atUs, + // An id makes it an async pair: requests overlap on their track. + id: r.requestId == null ? null : 'http-${r.requestId}', + interactionId: r.interactionId, + linkedBy: r.linkedBy, + args: { + 'url': r.url, + 'statusCode': r.statusCode, + 'durationMs': r.durationMs, + }, + ), + for (final QueryRecord r in TelescopeStore.recentQueries()) + _row( + kind: 'span', + track: 'db', + name: _clip(r.sql), + startUs: r.atUs - r.timeMs * 1000, + endUs: r.atUs, + interactionId: r.interactionId, + linkedBy: r.linkedBy, + args: {'sql': r.sql, 'timeMs': r.timeMs}, + ), + for (final EventRecord r in TelescopeStore.recentEvents()) + _row( + kind: 'instant', + track: 'events', + name: r.eventType, + startUs: r.atUs, + interactionId: r.interactionId, + linkedBy: r.linkedBy, + ), + for (final MagicModelRecord r in TelescopeStore.recentModels()) + _row( + kind: 'instant', + track: 'models', + name: '${r.modelClass} ${r.event}', + startUs: r.atUs, + interactionId: r.interactionId, + linkedBy: r.linkedBy, + args: {'key': r.modelKey}, + ), + for (final MagicCacheRecord r in TelescopeStore.recentCaches()) + _row( + kind: 'instant', + track: 'cache', + name: '${r.operation} ${r.key}', + startUs: r.atUs, + interactionId: r.interactionId, + linkedBy: r.linkedBy, + ), + ]; + static void _recordRouteTransition(String route, int durationMicros) { _routeTransitions.addLast({ 'route': route, @@ -214,11 +422,255 @@ class MagicPerfIntegration { static bool _observerRegistered = false; static FramePerfWatcher? _watcher; static final _RouteTransitionObserver _observer = _RouteTransitionObserver(); - static final Map _controllerNotifies = {}; + static final _MagicPerfSession _session = _MagicPerfSession(); static final Queue> _routeTransitions = Queue>(); } +/// One perfTimelineReader row, in the schema dusk documents on that pointer. +Map _row({ + required String kind, + required String track, + required String name, + required int startUs, + int? endUs, + String? id, + String? interactionId, + String? linkedBy, + Map? args, +}) => { + 'kind': kind, + 'track': track, + 'name': name, + 'startUs': startUs, + 'endUs': ?endUs, + 'id': ?id, + 'interactionId': ?interactionId, + 'linkedBy': ?linkedBy, + 'args': ?args, +}; + +String _path(String url) { + final Uri? uri = Uri.tryParse(url); + return uri == null || uri.path.isEmpty ? url : uri.path; +} + +/// A SQL string short enough to read as a slice name; the whole of it stays +/// in the row's args. +String _clip(String sql) => + sql.length <= 60 ? sql : '${sql.substring(0, 60)}...'; + +/// Everything `MagicPerfHooks.sink` delivered during one attribution session, +/// aggregated the way the report, the trace and the rules read it. +class _MagicPerfSession { + /// Sink rows kept for the trace. A session drives a handful of + /// interactions; this is minutes of notifies, not a memory concern. + static const int _maxRows = 2000; + + /// `FlutterTimeline.now` when the session opened, null before any has. + int? startUs; + + final Map controllerNotifies = {}; + final Map notifyCauses = {}; + final Map queryReloads = {}; + final Map actions = {}; + final Map events = {}; + final Map casts = {}; + final Map timerTicks = {}; + final Map broadcasts = {}; + + /// Cause name to controller type to notifies. + final Map> notifiesByCause = + >{}; + + /// Interaction id to model type to reloads that issued their own request. + final Map> uncachedReloads = + >{}; + + final Queue> rows = Queue>(); + + /// Row ids are never reused, so two sessions' spans cannot pair up in a + /// trace that happens to hold both. + int _rowSequence = 0; + + void open(int? atUs) { + startUs = atUs; + for (final Map counts in >[ + controllerNotifies, + notifyCauses, + queryReloads, + actions, + events, + casts, + timerTicks, + broadcasts, + notifiesByCause, + uncachedReloads, + ]) { + counts.clear(); + } + rows.clear(); + } + + /// The perfExtrasReader payload: exactly dusk's documented key set. + Map extras(List> routeTransitions) => + { + 'controllerNotifies': Map.of(controllerNotifies), + 'notifyCauses': Map.of(notifyCauses), + 'queryReloads': Map.of(queryReloads), + 'actions': Map.of(actions), + 'events': Map.of(events), + 'casts': Map.of(casts), + 'timerTicks': Map.of(timerTicks), + 'broadcasts': Map.of(broadcasts), + 'routeTransitions': routeTransitions, + }; + + /// The sink. Counts every event and keeps a trace row for each one with a + /// time on it; casts are counted only, since one runs per attribute read. + void record(MagicPerfEvent event) { + // Casts run once per attribute read, far too often to pay for a link + // lookup that no cast row would carry. + if (event is AttributeCast) { + _bump(casts, event.castType); + return; + } + // A span is reported when it ends, so it is linked from when it began. + final int? spanStartUs = switch (event) { + QueryReloaded(:final int startUs) => startUs, + ActionRan(:final int startUs) => startUs, + EventDispatched(:final int startUs) => startUs, + _ => null, + }; + final ({String? interactionId, String linkedBy}) link = + MagicPerfIntegration.interactionLink(startUs: spanStartUs); + + switch (event) { + case ControllerNotified(:final MagicController controller, :final cause): + final String type = controller.runtimeType.toString(); + _bump(controllerNotifies, type); + _bump(notifyCauses, cause.name); + _bump( + notifiesByCause.putIfAbsent(cause.name, () => {}), + type, + ); + _addRow( + 'instant', + 'magic.notify', + type, + link, + args: {'cause': cause.name}, + ); + case RepositoryUpserted(:final Type type, :final int count): + _addRow( + 'instant', + 'magic.repository', + '$type', + link, + args: {'count': count}, + ); + case QueryReloaded( + :final Type type, + :final int startUs, + :final int endUs, + :final bool fromCache, + ): + _bump(queryReloads, '$type'); + final String? interaction = link.interactionId; + if (!fromCache && interaction != null) { + _bump( + uncachedReloads.putIfAbsent(interaction, () => {}), + '$type', + ); + } + _addRow( + 'span', + 'magic.query', + '$type', + link, + startUs: startUs, + endUs: endUs, + args: {'fromCache': fromCache}, + ); + case ActionRan( + :final Type type, + :final int startUs, + :final int endUs, + :final ActionOutcome outcome, + ): + _bump(actions, '$type'); + _addRow( + 'span', + 'magic.action', + '$type', + link, + startUs: startUs, + endUs: endUs, + args: { + 'outcome': outcome.succeeded ? 'succeeded' : 'failed', + }, + ); + case EventDispatched( + :final Type type, + :final int listenerCount, + :final int startUs, + :final int endUs, + ): + _bump(events, '$type'); + _addRow( + 'span', + 'magic.event', + '$type', + link, + startUs: startUs, + endUs: endUs, + args: {'listeners': listenerCount}, + ); + case AttributeCast(): + // Counted before the link lookup. + break; + case TimerTicked(:final Type ownerType): + _bump(timerTicks, '$ownerType'); + _addRow('instant', 'magic.timer', '$ownerType', link); + case BroadcastReceived(:final String event): + _bump(broadcasts, event); + _addRow('instant', 'magic.broadcast', event, link); + } + } + + void _addRow( + String kind, + String track, + String name, + ({String? interactionId, String linkedBy}) link, { + int? startUs, + int? endUs, + Map? args, + }) { + rows.addLast( + _row( + kind: kind, + track: track, + name: name, + startUs: startUs ?? FlutterTimeline.now, + endUs: endUs, + // Spans overlap on their track (two queries reloading at once), so + // each gets an id and becomes an async pair in the trace. + id: kind == 'span' ? 'magic-${++_rowSequence}' : null, + interactionId: link.interactionId, + linkedBy: link.linkedBy, + args: args, + ), + ); + while (rows.length > _maxRows) { + rows.removeFirst(); + } + } + + static void _bump(Map counts, String key) => + counts.update(key, (int n) => n + 1, ifAbsent: () => 1); +} + /// Times a route push from the moment the navigator reports it to the first /// post-frame callback after it, which is the first point the new route has /// actually built and laid out. diff --git a/lib/src/telescope_integration.dart b/lib/src/telescope_integration.dart index 0981386..4e750b6 100644 --- a/lib/src/telescope_integration.dart +++ b/lib/src/telescope_integration.dart @@ -4,12 +4,14 @@ import 'package:fluttersdk_dusk/dusk.dart' import 'package:fluttersdk_telescope/telescope.dart'; import 'package:magic/magic.dart'; +import 'perf_integration.dart'; + /// Glues magic's Http / Model / Cache facades into the fluttersdk_telescope /// store. /// /// Host integration (debug-only): /// ```dart -/// if (kDebugMode) { +/// if (!kReleaseMode) { /// TelescopePlugin.install(); /// MagicTelescopeIntegration.install(); /// } @@ -44,6 +46,15 @@ class MagicTelescopeIntegration { /// Idempotent install. Safe to call multiple times within the same /// isolate lifetime. static void install() { + // magic's AuthInterceptor writes the bearer token under whatever header + // `auth.token.header` names; the store only knows the default names, so + // a renamed header would reach the agent-facing buffer in the clear. + // Ahead of the guard because a store reset drops the addition while + // this integration stays installed. + TelescopeRedaction.hideRequestHeaders([ + Config.get('auth.token.header', 'Authorization') ?? + 'Authorization', + ]); if (_installed) return; _installed = true; TelescopePlugin.registerHttpAdapter(MagicHttpFacadeAdapter()); @@ -158,7 +169,7 @@ class MagicHttpFacadeAdapter implements TelescopeHttpAdapter { } /// Number of HTTP requests currently in flight on Magic's network driver, - /// surfaced via the interceptor's FIFO `_pending` list. + /// surfaced via the interceptor's `_pending` list. /// /// Pre-install (or post-uninstall) `_interceptor` is null and the getter /// short-circuits to 0 ; the null-guard keeps `TelescopeStore.pendingHttpCount` @@ -168,31 +179,41 @@ class MagicHttpFacadeAdapter implements TelescopeHttpAdapter { } /// Internal interceptor ; translates Magic network lifecycle into -/// [HttpRequestRecord] entries. Pairs request → response/error via a -/// per-request stopwatch keyed on identity. +/// [HttpRequestRecord] entries. /// -/// FIFO attribution (`attributedHeuristically: true`) is used because -/// `MagicNetworkInterceptor` does not carry a correlation handle across -/// `onRequest` / `onResponse` calls ; best-effort matching by call order. +/// Pairs each answer with its request by the id the driver stamps on +/// [MagicRequest.id] and carries onto [MagicResponse.id] / [MagicError.id], +/// so two requests completing out of order keep their own URL and duration. +/// Only an answer without an id (a hand-built one; `Http.fake` installs no +/// interceptors, so its traffic never reaches this one) falls back to the +/// oldest id-less request in flight, and that record says so with +/// `attributedHeuristically: true`. class _TelescopeNetworkInterceptor extends MagicNetworkInterceptor { /// Set to true by [MagicHttpFacadeAdapter.uninstall] ; drops every /// subsequent record. bool _disarmed = false; - /// In-flight requests, FIFO. We pair onResponse/onError with the - /// oldest pending request. + /// In-flight requests, oldest first. final List<_InFlight> _pending = <_InFlight>[]; @override dynamic onRequest(MagicRequest request) { if (_disarmed) return request; + // The interaction is read HERE, in the zone the request was sent from; + // the answer arrives on a socket callback that may not carry it. + final ({String? interactionId, String linkedBy}) link = + MagicPerfIntegration.interactionLink(); _pending.add( _InFlight( + id: request.id, url: request.url, method: request.method, startedAt: DateTime.now(), + startUs: FlutterTimeline.now, requestHeaders: _stringHeaders(request.headers), - requestBody: _truncate(request.data), + requestBody: _truncate(_redactRequestBody(request.data)), + interactionId: link.interactionId, + linkedBy: link.linkedBy, ), ); return request; @@ -202,9 +223,10 @@ class _TelescopeNetworkInterceptor extends MagicNetworkInterceptor { dynamic onResponse(MagicResponse response) { if (_disarmed) return response; _record( + id: response.id, statusCode: response.statusCode, isError: response.failed, - responseBody: _truncate(response.data), + responseBody: _truncate(_redactResponseBody(response.data)), ); return response; } @@ -213,38 +235,50 @@ class _TelescopeNetworkInterceptor extends MagicNetworkInterceptor { dynamic onError(MagicError error) { if (_disarmed) return error; _record( + id: error.id, statusCode: error.statusCode, isError: true, - responseBody: error.message ?? _truncate(error.response?.data), + responseBody: + error.message ?? _truncate(_redactResponseBody(error.response?.data)), ); return error; } - /// 1. Pull the oldest in-flight (FIFO best-effort). - /// 2. Compute duration from the captured timestamp. + /// 1. Take the request this answer belongs to: by [id], or the oldest in + /// flight that carries no id either when the answer has none. A request + /// with an id is never handed to an id-less answer: its own answer + /// would then find nothing to pair with and be dropped. + /// 2. Time it on the monotonic clock the rest of the trace uses. /// 3. Push a HttpRequestRecord into the store. void _record({ + required int? id, required int statusCode, required bool isError, required String? responseBody, }) { - if (_pending.isEmpty) return; - final _InFlight pending = _pending.removeAt(0); - final int durationMs = DateTime.now() - .difference(pending.startedAt) - .inMilliseconds; + final int index = _pending.indexWhere((_InFlight p) => p.id == id); + // An id nothing is waiting for: its request went out before install. + if (index == -1) return; + final _InFlight pending = _pending.removeAt(index); + + final int endUs = FlutterTimeline.now; TelescopeStore.recordHttp( HttpRequestRecord( url: pending.url, method: pending.method, statusCode: statusCode, - durationMs: durationMs, + durationMs: (endUs - pending.startUs) ~/ 1000, isError: isError, timestamp: pending.startedAt, requestHeaders: pending.requestHeaders, requestBody: pending.requestBody, responseBody: responseBody, - attributedHeuristically: true, + attributedHeuristically: id == null, + requestId: pending.id?.toString(), + startUs: pending.startUs, + endUs: endUs, + interactionId: pending.interactionId, + linkedBy: pending.linkedBy, ), ); } @@ -254,18 +288,26 @@ class _TelescopeNetworkInterceptor extends MagicNetworkInterceptor { /// between `onRequest` and `onResponse`/`onError`. class _InFlight { _InFlight({ + required this.id, required this.url, required this.method, required this.startedAt, + required this.startUs, required this.requestHeaders, required this.requestBody, + required this.interactionId, + required this.linkedBy, }); + final int? id; final String url; final String method; final DateTime startedAt; + final int startUs; final Map? requestHeaders; final String? requestBody; + final String? interactionId; + final String linkedBy; } /// Coerce a `Map` headers map into the @@ -279,6 +321,24 @@ Map? _stringHeaders(Map raw) { return out; } +/// Mask the credential keys of a request body before [_truncate] cuts +/// and stringifies it. +/// +/// Neither a Dart structure's `toString()` nor a cut JSON string parses, so +/// the store's own JSON masking could not see the body afterwards. Returns +/// a masked copy: the driver sends on the very object the interceptor saw, +/// so masking in place would send the mask to the server. +Object? _redactRequestBody(Object? data) => + _redactBody(data, TelescopeRedaction.hiddenRequestParameters); + +/// [_redactRequestBody] against the response list. +Object? _redactResponseBody(Object? data) => + _redactBody(data, TelescopeRedaction.hiddenResponseParameters); + +Object? _redactBody(Object? data, Set keys) => data is String + ? TelescopeRedaction.redactBody(data, keys) + : TelescopeRedaction.redactParameters(data, keys); + /// Render an arbitrary request/response body into the bounded string /// [HttpRequestRecord] expects. Truncates at 8 KB to keep the ring /// buffer affordable. @@ -343,6 +403,8 @@ class _ModelLifecycleListener extends MagicListener { Future handle(ModelEvent event) async { final Model model = event.model; final dynamic key = model.id; + final ({String? interactionId, String linkedBy}) link = + MagicPerfIntegration.interactionLink(); TelescopeStore.recordMagicModel( MagicModelRecord( modelClass: model.runtimeType.toString(), @@ -350,6 +412,8 @@ class _ModelLifecycleListener extends MagicListener { modelKey: key == null ? '' : key.toString(), time: DateTime.now(), attributes: Map.from(model.attributes), + interactionId: link.interactionId, + linkedBy: link.linkedBy, ), ); } @@ -436,8 +500,17 @@ class _CacheListener extends MagicListener { } else { key = '*'; } + final ({String? interactionId, String linkedBy}) link = + MagicPerfIntegration.interactionLink(); TelescopeStore.recordMagicCache( - MagicCacheRecord(operation: op, key: key, time: DateTime.now(), ttl: ttl), + MagicCacheRecord( + operation: op, + key: key, + time: DateTime.now(), + ttl: ttl, + interactionId: link.interactionId, + linkedBy: link.linkedBy, + ), ); } } @@ -528,11 +601,15 @@ class _EventToRecord extends MagicListener { @override Future handle(T event) async { + final ({String? interactionId, String linkedBy}) link = + MagicPerfIntegration.interactionLink(); TelescopeStore.recordEvent( EventRecord( eventType: eventTypeName, payload: const {}, time: DateTime.now(), + interactionId: link.interactionId, + linkedBy: link.linkedBy, ), ); } @@ -643,6 +720,8 @@ class MagicQueryWatcher implements TelescopeWatcher { class _QueryExecutedListener extends MagicListener { @override Future handle(QueryExecuted event) async { + final ({String? interactionId, String linkedBy}) link = + MagicPerfIntegration.interactionLink(); TelescopeStore.recordQuery( QueryRecord( sql: event.sql, @@ -650,6 +729,8 @@ class _QueryExecutedListener extends MagicListener { timeMs: event.timeMs, connectionName: event.connectionName, time: DateTime.now(), + interactionId: link.interactionId, + linkedBy: link.linkedBy, ), ); } diff --git a/lib/telescope.dart b/lib/telescope.dart index de86c9a..d662015 100644 --- a/lib/telescope.dart +++ b/lib/telescope.dart @@ -13,11 +13,11 @@ /// boot errors: /// /// ```dart -/// if (kDebugMode) { +/// if (!kReleaseMode) { /// TelescopePlugin.install(); /// } /// await Magic.init(configFactories: [...]); -/// if (kDebugMode) { +/// if (!kReleaseMode) { /// MagicTelescopeIntegration.install(); /// } /// ``` diff --git a/pubspec.yaml b/pubspec.yaml index 618176c..427b38c 100644 --- a/pubspec.yaml +++ b/pubspec.yaml @@ -12,10 +12,10 @@ environment: dependencies: flutter: sdk: flutter - magic: ^0.0.22 - fluttersdk_dusk: ^0.0.16 - fluttersdk_telescope: ^0.0.7 - fluttersdk_wind: ^1.7.0 + magic: ^0.0.24 + fluttersdk_dusk: ^0.0.17 + fluttersdk_telescope: ^0.0.9 + fluttersdk_wind: ^1.8.0 dev_dependencies: flutter_test: diff --git a/test/perf_insight_rules_test.dart b/test/perf_insight_rules_test.dart new file mode 100644 index 0000000..9942cd4 --- /dev/null +++ b/test/perf_insight_rules_test.dart @@ -0,0 +1,443 @@ +import 'package:flutter/material.dart'; +import 'package:flutter_test/flutter_test.dart'; +import 'package:fluttersdk_dusk/dusk.dart' + show + PerfMode, + buildPerfReport, + framePerfReader, + perfExtrasReader, + perfSessionBeginHook, + perfSessionEndHook; +import 'package:fluttersdk_telescope/telescope.dart'; +import 'package:magic/magic.dart'; +import 'package:magic_devtools/magic_devtools.dart'; + +/// Tests for [PerfInsightRules], the wind and magic rules `perf_end` runs +/// through dusk's contributor seam. +/// +/// Every rule is pinned twice, once just past its threshold and once just +/// short of it: a rule that only has a firing case would pass with no +/// threshold at all. + +class _StormController extends MagicController {} + +/// A report as dusk hands it to a contributor, cut to the keys the rules read. +Map _report({ + int painted = 10, + double? durationMs = 1000, + List routeTransitions = const [], + String mode = 'attribution', +}) => { + 'mode': mode, + 'coverage': {'framesSummarized': painted}, + 'summary': { + 'durationMs': durationMs, + 'routeTransitions': routeTransitions, + }, +}; + +PerfRuleInputs _inputs({ + Map extras = const {}, + Map? wind, + Map> notifiesByCause = + const >{}, + Map> uncachedReloads = + const >{}, + Map> httpByInteraction = const >{}, +}) => PerfRuleInputs( + extras: extras, + wind: wind, + notifiesByCause: notifiesByCause, + uncachedReloads: uncachedReloads, + httpByInteraction: httpByInteraction, +); + +List _metrics(List> insights) => insights + .map( + (Map i) => + (i['evidence']! as Map)['metric']! as String, + ) + .toList(); + +FramePerfRecord _frame(int frameNumber) => FramePerfRecord( + frameNumber: frameNumber, + buildMicros: 4000, + rasterMicros: 2000, + vsyncOverheadMicros: 1000, + totalSpanMicros: 7000, + time: DateTime(2026, 9, 28), + blocks: const {}, +); + +void main() { + group('wind rules', () { + test('a wrapper emitted at or past half a W-widget build per build and 20 ' + 'per frame is named, one short of either is not', () { + Map wind(int mouseRegions) => { + 'widgetBuilds': {'WDiv': 300, 'WButton': 100}, + 'wrapperEmissions': { + 'MouseRegion': mouseRegions, + 'Padding': 50, + }, + }; + + final List> fired = PerfInsightRules.evaluate( + _report(), + _inputs(wind: wind(200)), + ); + expect(_metrics(fired), contains('wind.wrapperEmissions.MouseRegion')); + expect( + PerfInsightRules.evaluate(_report(), _inputs(wind: wind(199))), + isEmpty, + ); + expect( + PerfInsightRules.evaluate( + _report(painted: 11), + _inputs(wind: wind(200)), + ), + isEmpty, + reason: '200 over 11 frames is under 20 per frame', + ); + }); + + test('mediaQuerySize reads at 10 per painted frame fire, below do not', () { + Map wind(int reads) => { + 'inheritedReads': {'mediaQuerySize': reads}, + }; + + expect( + _metrics( + PerfInsightRules.evaluate(_report(), _inputs(wind: wind(100))), + ), + ['wind.inheritedReads.mediaQuerySize'], + ); + expect( + PerfInsightRules.evaluate(_report(), _inputs(wind: wind(99))), + isEmpty, + ); + }); + + test('the mediaQuerySize summary describes a size-only subscription', () { + final Map insight = PerfInsightRules.evaluate( + _report(), + _inputs( + wind: { + 'inheritedReads': {'mediaQuerySize': 100}, + }, + ), + ).single; + + // wind reads MediaQuery.sizeOf: a resize or a rotation rebuilds the + // reader, a keyboard inset does not. The old text said the opposite. + final String summary = insight['summary']! as String; + expect(summary, contains('MediaQuery.sizeOf')); + expect(summary, contains('resize')); + expect(summary, contains('not a keyboard inset')); + expect(summary, isNot(contains('MediaQuery.of'))); + expect(summary, isNot(contains('EVERY'))); + }); + + test('parse misses on a warm surface fire; a session that navigated, or ' + 'a low miss rate, does not', () { + final Map misses = { + 'cacheHits': 180, + 'cacheMisses': 20, + }; + + expect( + _metrics(PerfInsightRules.evaluate(_report(), _inputs(wind: misses))), + ['wind.cacheMisses'], + ); + expect( + PerfInsightRules.evaluate( + _report( + routeTransitions: [ + {'route': '/monitors', 'ms': 12.0}, + ], + ), + _inputs(wind: misses), + ), + isEmpty, + reason: 'a first visit to a route is expected to miss', + ); + expect( + PerfInsightRules.evaluate( + _report(), + _inputs(wind: {'cacheHits': 181, 'cacheMisses': 20}), + ), + isEmpty, + ); + expect( + PerfInsightRules.evaluate( + _report(), + _inputs(wind: {'cacheHits': 0, 'cacheMisses': 19}), + ), + isEmpty, + ); + }); + }); + + group('magic rules', () { + test('a notify cause at 2 per painted frame fires and names its ' + 'controller; below does not', () { + final List> fired = PerfInsightRules.evaluate( + _report(), + _inputs( + notifiesByCause: >{ + 'repositoryQuery': {'MonitorController': 20}, + }, + ), + ); + expect(_metrics(fired), ['magic.notifyCauses.repositoryQuery']); + expect(fired.single['title'], contains('MonitorController')); + + expect( + PerfInsightRules.evaluate( + _report(), + _inputs( + notifiesByCause: >{ + 'repositoryQuery': {'MonitorController': 19}, + }, + ), + ), + isEmpty, + ); + }); + + test('timer-tick notifies at 4 per second fire, and are not reported a ' + 'second time as a per-frame storm', () { + Map> ticks(int n) => >{ + 'timerTick': {'CountdownController': n}, + }; + + expect( + _metrics( + PerfInsightRules.evaluate( + _report(painted: 2, durationMs: 5000), + _inputs(notifiesByCause: ticks(20)), + ), + ), + ['magic.notifyCauses.timerTick'], + ); + expect( + PerfInsightRules.evaluate( + _report(painted: 2, durationMs: 5000), + _inputs(notifiesByCause: ticks(19)), + ), + isEmpty, + ); + }); + + test('a query reloaded twice without cache in one interaction fires', () { + expect( + _metrics( + PerfInsightRules.evaluate( + _report(), + _inputs( + uncachedReloads: >{ + 'i2': {'Monitor': 2}, + }, + ), + ), + ), + ['magic.queryReloads.uncached'], + ); + expect( + PerfInsightRules.evaluate( + _report(), + _inputs( + uncachedReloads: >{ + 'i2': {'Monitor': 1}, + 'i3': {'Monitor': 1}, + }, + ), + ), + isEmpty, + ); + }); + + test('casts at 50 per painted frame fire, below do not', () { + expect( + _metrics( + PerfInsightRules.evaluate( + _report(), + _inputs( + extras: { + 'casts': {'datetime': 400, 'json': 100}, + }, + ), + ), + ), + ['magic.casts'], + ); + expect( + PerfInsightRules.evaluate( + _report(), + _inputs( + extras: { + 'casts': {'datetime': 499}, + }, + ), + ), + isEmpty, + ); + }); + + test( + 'five requests in one interaction, or the same request twice, fire', + () { + expect( + _metrics( + PerfInsightRules.evaluate( + _report(), + _inputs( + httpByInteraction: >{ + 'i1': [ + 'GET /a', + 'GET /b', + 'GET /c', + 'GET /d', + 'GET /e', + ], + }, + ), + ), + ), + ['magic.httpPerInteraction'], + ); + expect( + _metrics( + PerfInsightRules.evaluate( + _report(), + _inputs( + httpByInteraction: >{ + 'i1': ['GET /a', 'GET /a'], + }, + ), + ), + ), + ['magic.httpPerInteraction'], + ); + expect( + PerfInsightRules.evaluate( + _report(), + _inputs( + httpByInteraction: >{ + 'i1': ['GET /a', 'GET /b', 'GET /c', 'GET /d'], + }, + ), + ), + isEmpty, + ); + }, + ); + + test('a timing report gets no rule at all', () { + expect( + PerfInsightRules.evaluate( + _report(mode: 'timing'), + _inputs( + extras: { + 'casts': {'datetime': 5000}, + }, + ), + ), + isEmpty, + ); + }); + }); + + group('conformance through dusk buildPerfReport', () { + setUp(() { + MagicApp.reset(); + Magic.flush(); + MagicRouter.reset(); + MagicPerfIntegration.resetForTesting(); + TelescopeStore.resetForTesting(); + WindParser.clearCache(); + WindPerfCounters.reset(); + }); + + tearDown(() { + MagicPerfIntegration.resetForTesting(); + MagicRouter.reset(); + TelescopeStore.resetForTesting(); + WindPerfCounters.enabled = false; + WindPerfCounters.reset(); + }); + + testWidgets('a report built from the real readers carries a wind and a ' + 'magic insight, each well formed', (WidgetTester tester) async { + MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); + + // 1. wind: forty h-full boxes read MediaQuery size forty times. + await tester.pumpWidget( + MaterialApp( + home: WindTheme( + data: WindThemeData(), + child: Column( + children: [ + for (int i = 0; i < 40; i++) + const Expanded(child: WDiv(className: 'h-full')), + ], + ), + ), + ), + ); + + // 2. magic: one controller notifying far more often than frames paint. + final _StormController controller = _StormController(); + for (int i = 0; i < 20; i++) { + controller.refreshUI(); + } + + // 3. Two painted frames, as telescope's frame watcher records them. + TelescopeStore.recordFramePerf(_frame(1)); + TelescopeStore.recordFramePerf(_frame(2)); + + final Map report = buildPerfReport( + framePerfReader(), + perfExtrasReader(), + const WindPerfResolverImpl().stats(), + env: const {'platform': 'test'}, + framesDrawn: 2, + durationMs: 500, + ); + perfSessionEndHook(); + + final List> insights = + (report['insights']! as List).cast>(); + expect( + insights.map((Map i) => i['title']), + isNot(contains(startsWith('Insight contributor'))), + reason: 'a malformed contributed insight becomes a failure insight', + ); + for (final Map insight in insights) { + expect( + insight.keys, + containsAll([ + 'id', + 'severity', + 'title', + 'evidence', + 'nextStep', + ]), + ); + } + final List metrics = _metrics(insights); + expect(metrics, contains('wind.inheritedReads.mediaQuerySize')); + expect(metrics, contains('magic.notifyCauses.direct')); + for (final Map insight in insights.where( + (Map i) => + _metrics(>[i]).single.contains('.'), + )) { + expect( + (insight['evidence']! as Map)['threshold'], + isA>(), + reason: 'a contributed rule states the threshold it fired on', + ); + } + }); + }); +} diff --git a/test/perf_integration_test.dart b/test/perf_integration_test.dart index cbd492a..45292f0 100644 --- a/test/perf_integration_test.dart +++ b/test/perf_integration_test.dart @@ -1,13 +1,17 @@ +import 'dart:async'; import 'dart:ui' show FrameTiming, PlatformDispatcher, TimingsCallback; import 'package:flutter/material.dart'; import 'package:flutter_test/flutter_test.dart'; import 'package:fluttersdk_dusk/dusk.dart' show + PerfMode, framePerfReader, perfExtrasReader, + perfInsightContributors, perfSessionBeginHook, - perfSessionEndHook; + perfSessionEndHook, + perfTimelineReader; import 'package:fluttersdk_telescope/telescope.dart'; import 'package:magic/magic.dart'; import 'package:magic_devtools/magic_devtools.dart'; @@ -73,7 +77,7 @@ FramePerfRecord _frameRecord(int frameNumber) => FramePerfRecord( vsyncOverheadMicros: 1000, totalSpanMicros: 7000, time: DateTime(2026, 8, 25), - blocks: const {}, + blocks: const {}, ); /// Moves wind's counters the way the app does: by building a real W-widget. @@ -111,6 +115,49 @@ Future _warmTheParseCache(WidgetTester tester) async { WindPerfCounters.reset(); } +/// Stands in for dusk's `PerfInteraction`, whose constructor is private to +/// dusk: a host test cannot open a real one without driving a perf session over +/// the VM Service. Carries the same window (`startUs`, `closedAtUs`) the real +/// handle does, which is all the span link reads. +class _FakeHandle { + const _FakeHandle(this.id, {required this.startUs, this.closedAtUs}); + + final String id; + + final int startUs; + + final int? closedAtUs; +} + +/// Points the two seams `interactionLink` resolves a span through at +/// [_FakeHandle]: the zone value, and dusk's `perfInteractionAt` over [log]. +/// The lookup is the same rule dusk applies: newest window holding the time. +void _useFakeHandles({List<_FakeHandle> log = const <_FakeHandle>[]}) { + MagicPerfIntegration.zoneInteraction = (Object? value) => value is _FakeHandle + ? (id: value.id, startUs: value.startUs, closedAtUs: value.closedAtUs) + : null; + MagicPerfIntegration.interactionIdAt = (int us) { + for (final _FakeHandle handle in log.reversed) { + if (us >= handle.startUs && us <= (handle.closedAtUs ?? us)) { + return handle.id; + } + } + return null; + }; +} + +/// Delivers [event] to the sink the way magic does, from inside [handle]'s +/// zone: the zone a timer or a request created during a gesture keeps. +void _emitInZone(_FakeHandle handle, MagicPerfEvent event) => runZoned( + () => MagicPerfHooks.emit(event), + zoneValues: {#fluttersdk_interaction: handle}, +); + +/// The one trace row on [track], asserting there is exactly one. +Map _rowOn(String track) => perfTimelineReader().singleWhere( + (Map r) => r['track'] == track, +); + void main() { setUpAll(() { TestWidgetsFlutterBinding.ensureInitialized(); @@ -170,6 +217,7 @@ void main() { test('attributes notify counts to each controller runtime type', () { MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); final _AlphaController alpha = _AlphaController(); final _BetaController beta = _BetaController(); @@ -223,21 +271,117 @@ void main() { expect(payload['livenessCounter'], isA()); }); - test('perfExtrasReader returns the notify counts', () { + test('perfExtrasReader returns exactly dusk\'s documented key set', () { MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); _AlphaController().refreshUI(); final Map payload = perfExtrasReader(); + // dusk ignores an unknown key rather than failing the report, so a + // renamed key would read as an empty section; pinned here instead. expect( payload.keys, - unorderedEquals(['controllerNotifies', 'routeTransitions']), + unorderedEquals([ + 'controllerNotifies', + 'notifyCauses', + 'queryReloads', + 'actions', + 'events', + 'casts', + 'timerTicks', + 'broadcasts', + 'routeTransitions', + ]), ); expect(payload['controllerNotifies'], { '_AlphaController': 1, }); + expect(payload['notifyCauses'], {'direct': 1}); expect(payload['routeTransitions'], isEmpty); }); + test('a timing session installs no sink and leaves wind counting off', () { + MagicPerfIntegration.install(); + + perfSessionBeginHook(PerfMode.timing); + _AlphaController().refreshUI(); + + expect(MagicPerfHooks.sink, isNull); + expect(WindPerfCounters.enabled, isFalse); + expect(MagicPerfIntegration.controllerNotifyCounts, isEmpty); + }); + + test('the end hook removes the sink', () { + MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); + expect(MagicPerfHooks.sink, isNotNull); + + perfSessionEndHook(); + _AlphaController().refreshUI(); + + expect(MagicPerfHooks.sink, isNull); + expect(MagicPerfIntegration.controllerNotifyCounts, {}); + }); + + test('perfTimelineReader carries sink rows and telescope records in ' + 'dusk\'s row schema, stamped with their link', () { + MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); + _AlphaController().refreshUI(); + MagicPerfHooks.emit(QueryReloaded(_AlphaController, 100, 250, false)); + TelescopeStore.recordHttp( + HttpRequestRecord( + url: 'https://api.test/monitors?page=1', + method: 'GET', + statusCode: 200, + durationMs: 3, + isError: false, + timestamp: DateTime(2026, 9, 28), + requestId: '7', + startUs: 1000, + endUs: 4000, + interactionId: 'i1', + linkedBy: 'zone', + ), + ); + + final List> rows = perfTimelineReader(); + final Map notify = rows.firstWhere( + (Map r) => r['track'] == 'magic.notify', + ); + expect(notify['kind'], 'instant'); + expect(notify['name'], '_AlphaController'); + expect(notify['linkedBy'], 'window'); + expect(notify['startUs'], isA()); + + final Map query = rows.firstWhere( + (Map r) => r['track'] == 'magic.query', + ); + expect(query['kind'], 'span'); + expect(query['startUs'], 100); + expect(query['endUs'], 250); + expect(query['id'], isNotNull); + + final Map http = rows.firstWhere( + (Map r) => r['track'] == 'http', + ); + expect(http['name'], 'GET /monitors'); + expect(http['id'], 'http-7'); + expect(http['startUs'], 1000); + expect(http['endUs'], 4000); + expect(http['interactionId'], 'i1'); + expect(http['linkedBy'], 'zone'); + }); + + test('install appends one insight contributor, however often it runs', () { + final int before = perfInsightContributors.length; + + MagicPerfIntegration.install(); + MagicPerfIntegration.install(); + + expect(perfInsightContributors, hasLength(before + 1)); + }); + testWidgets('perfExtrasReader carries a named, timed route transition', ( WidgetTester tester, ) async { @@ -283,8 +427,10 @@ void main() { ); MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); _AlphaController().refreshUI(); - perfSessionBeginHook(); + expect(MagicPerfIntegration.controllerNotifyCounts, isNotEmpty); + perfSessionBeginHook(PerfMode.attribution); expect(WindPerfCounters.cacheHits, 0); expect(TelescopeStore.recentFramePerf(), isEmpty); @@ -306,7 +452,7 @@ void main() { MagicPerfIntegration.install(); expect(WindPerfCounters.enabled, isFalse); - perfSessionBeginHook(); + perfSessionBeginHook(PerfMode.attribution); // Zeroing without enabling would report a wind section of all zeros // beside populated frame and magic sections, with no error to say why. @@ -323,17 +469,82 @@ void main() { }); }); + group('span interaction links', () { + // A closed at 5000, B still open. Times are FlutterTimeline microseconds. + const _FakeHandle a = _FakeHandle('i1', startUs: 1000, closedAtUs: 5000); + const _FakeHandle b = _FakeHandle('i2', startUs: 6000); + + setUp(() { + MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); + _useFakeHandles(log: <_FakeHandle>[a, b]); + }); + + test('a reload that outlives its interaction\'s close still links zone ' + 'to that interaction', () { + // Started at 2000, inside A's window, and finished at 9000, four + // seconds after A settled: resolving at the end would call A absent. + _emitInZone(a, QueryReloaded(_AlphaController, 2000, 9000, false)); + + final Map row = _rowOn('magic.query'); + expect(row['interactionId'], 'i1'); + expect(row['linkedBy'], 'zone'); + }); + + test('a reload started during A and ended during B links to A, not to ' + 'the zone handle it ended in', () { + _emitInZone(b, QueryReloaded(_AlphaController, 2000, 7000, false)); + + final Map row = _rowOn('magic.query'); + expect(row['interactionId'], 'i1'); + expect(row['linkedBy'], 'frame'); + }); + + test('an action and an event resolve from their start the same way', () { + _emitInZone( + b, + ActionRan( + _AlphaController, + 2000, + 7000, + const ActionSucceeded(null), + ), + ); + _emitInZone(b, EventDispatched(_BetaController, 1, 2500, 7000)); + + expect(_rowOn('magic.action')['interactionId'], 'i1'); + expect(_rowOn('magic.event')['interactionId'], 'i1'); + }); + + test('a span that began outside every window links by window', () { + _emitInZone(b, QueryReloaded(_AlphaController, 500, 7000, false)); + + final Map row = _rowOn('magic.query'); + expect(row.containsKey('interactionId'), isFalse); + expect(row['linkedBy'], 'window'); + }); + + test('an instant with no start time still needs an OPEN zone handle', () { + _emitInZone(a, TimerTicked(_AlphaController)); + + final Map row = _rowOn('magic.timer'); + expect(row.containsKey('interactionId'), isFalse); + expect(row['linkedBy'], 'window'); + }); + }); + group('MagicPerfIntegration.resetForTesting', () { - test('restores the hook, the counters and all four pointers', () { + test('restores the sink, the counters and every pointer', () { + final int contributors = perfInsightContributors.length; MagicPerfIntegration.install(); + perfSessionBeginHook(PerfMode.attribution); _AlphaController().refreshUI(); - perfSessionBeginHook(); TelescopeStore.recordFramePerf(_frameRecord(5)); MagicPerfIntegration.resetForTesting(); expect(MagicPerfIntegration.isInstalled, isFalse); - expect(MagicController.onRefreshUI, isNull); + expect(MagicPerfHooks.sink, isNull); expect(MagicPerfIntegration.controllerNotifyCounts, isEmpty); // A reset that left counting on would tax every later test in the suite. expect(WindPerfCounters.enabled, isFalse); @@ -343,12 +554,26 @@ void main() { }); expect(perfExtrasReader(), { 'controllerNotifies': {}, + 'notifyCauses': {}, + 'queryReloads': {}, + 'actions': {}, + 'events': {}, + 'casts': {}, + 'timerTicks': {}, + 'broadcasts': {}, 'routeTransitions': >[], }); + expect(perfTimelineReader(), isEmpty); + expect(perfInsightContributors, hasLength(contributors)); + expect( + MagicPerfIntegration.zoneInteraction(Object()), + isNull, + reason: 'only a real open dusk interaction counts as a zone handle', + ); // The restored hooks are no-ops: the frame buffer survives the begin // hook and counting stays off after the end hook. - perfSessionBeginHook(); + perfSessionBeginHook(PerfMode.attribution); perfSessionEndHook(); expect(TelescopeStore.recentFramePerf(), hasLength(1)); expect(WindPerfCounters.enabled, isFalse); diff --git a/test/telescope_integration_test.dart b/test/telescope_integration_test.dart index 7c6e9f3..4b93f18 100644 --- a/test/telescope_integration_test.dart +++ b/test/telescope_integration_test.dart @@ -1,6 +1,12 @@ -import 'package:flutter_test/flutter_test.dart'; +import 'dart:async'; +import 'dart:convert'; +import 'dart:io'; + +import 'package:flutter/material.dart'; +import 'package:flutter_test/flutter_test.dart' hide EventDispatcher; import 'package:fluttersdk_telescope/telescope.dart'; import 'package:magic/magic.dart'; +import 'package:magic_devtools/magic_devtools.dart'; import 'package:magic_devtools/telescope.dart'; // --------------------------------------------------------------------------- @@ -87,11 +93,72 @@ class _CapturingNetworkDriver implements NetworkDriver { }) => throw UnimplementedError(); } -MagicRequest _req(String url, {String method = 'GET'}) => - MagicRequest(url: url, method: method); +MagicRequest _req(String url, {String method = 'GET', int? id}) => + MagicRequest(url: url, method: method, id: id); + +MagicResponse _ok({int statusCode = 200, int? id}) => + MagicResponse(data: {}, statusCode: statusCode, id: id); + +/// Stands in for dusk's `PerfInteraction`, whose constructor is private to +/// dusk: a host test has no way to open a real one outside a perf session +/// driven over the VM Service. Recognised through +/// [MagicPerfIntegration.zoneInteraction], the one seam that decides what a +/// zone value is; the zone key and the zone, frame, window order under test +/// are the production ones. +class _FakeInteraction { + _FakeInteraction(this.id); + + final String id; + + bool open = true; +} + +/// Points both interaction sources at [_FakeInteraction]: the zone value, and +/// the active slot a frame-zone read falls back to. +void _useFakeInteractions({_FakeInteraction? active}) { + // An instant (these records carry no start time) needs an OPEN handle, so a + // closed one only has to report that it closed. + MagicPerfIntegration.zoneInteraction = (Object? value) => + value is _FakeInteraction + ? (id: value.id, startUs: 0, closedAtUs: value.open ? null : 1) + : null; + MagicPerfIntegration.activeInteractionId = () => + active != null && active.open ? active.id : null; +} + +/// Runs [body] the way dusk runs a gesture: with [interaction] as the zone +/// value under dusk's public `#fluttersdk_interaction` key. +R _inInteraction(_FakeInteraction interaction, R Function() body) => + runZoned( + body, + zoneValues: {#fluttersdk_interaction: interaction}, + ); -MagicResponse _ok({int statusCode = 200}) => - MagicResponse(data: {}, statusCode: statusCode); +class _NextPage extends StatefulWidget { + const _NextPage(); + + @override + State<_NextPage> createState() => _NextPageState(); +} + +class _NextPageState extends State<_NextPage> { + @override + void initState() { + super.initState(); + // The refetch a newly mounted screen fires: it runs in the frame zone, + // which never carries the zone value of the tap that navigated here. + EventDispatcher.instance.dispatch( + QueryExecuted( + sql: 'select * from next', + bindings: [], + timeMs: 1, + ), + ); + } + + @override + Widget build(BuildContext context) => const Text('next'); +} void main() { group('MagicHttpFacadeAdapter.pendingCount', () { @@ -151,6 +218,30 @@ void main() { expect(adapter.pendingCount, equals(0)); }); + test('an answer without an id never takes a request that has one', () { + // It used to take the oldest request in flight whatever that was. When + // that was a real request with an id, its own answer then found nothing + // to pair with and was dropped, and the id-less answer was recorded + // against the wrong URL. + TelescopeStore.resetForTesting(); + adapter.install(); + final interceptor = driver.interceptors.first; + + interceptor.onRequest(_req('/real', id: 7)); + interceptor.onRequest(_req('/hand-built')); + interceptor.onResponse(_ok(statusCode: 201)); + interceptor.onResponse(_ok(id: 7)); + + final Map byUrl = { + for (final HttpRequestRecord r in TelescopeStore.recentHttp()) r.url: r, + }; + expect(byUrl['/hand-built']?.statusCode, 201); + expect(byUrl['/hand-built']?.attributedHeuristically, isTrue); + expect(byUrl['/real']?.statusCode, 200); + expect(byUrl['/real']?.requestId, '7'); + expect(adapter.pendingCount, 0); + }); + test( 'returns 0 again after uninstall() clears the interceptor reference', () { @@ -180,4 +271,371 @@ void main() { expect(TelescopeStore.pendingHttpCount, equals(1)); }); }); + + group('HTTP pairing by request id', () { + late HttpServer server; + HttpOverrides? bindingOverrides; + + setUp(() async { + // The widget binding a testWidgets case in this file creates installs a + // global HttpClient override that answers every request 400; these + // cases need the real loopback socket. + bindingOverrides = HttpOverrides.current; + HttpOverrides.global = null; + MagicApp.reset(); + Magic.flush(); + TelescopeStore.resetForTesting(); + MagicPerfIntegration.resetForTesting(); + + server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); + server.listen((HttpRequest request) async { + final int delayMs = request.uri.path == '/slow' ? 400 : 0; + await Future.delayed(Duration(milliseconds: delayMs)); + request.response + ..statusCode = 200 + ..headers.contentType = ContentType.json + ..write('{"path":"${request.uri.path}"}'); + await request.response.close(); + }); + }); + + tearDown(() async { + await server.close(force: true); + HttpOverrides.global = bindingOverrides; + TelescopeStore.resetForTesting(); + MagicPerfIntegration.resetForTesting(); + MagicApp.reset(); + Magic.flush(); + }); + + test('two responses completing out of order each keep their own URL and ' + 'duration', () async { + final DioNetworkDriver driver = DioNetworkDriver( + baseUrl: 'http://127.0.0.1:${server.port}', + ); + Magic.bind('network', () => driver); + final MagicHttpFacadeAdapter adapter = MagicHttpFacadeAdapter() + ..install(); + + // /slow is sent first and answers last, which is exactly the order a + // FIFO pairing gets wrong: it hands /fast's answer to /slow. + final Future slow = driver.get('/slow'); + final Future fast = driver.get('/fast'); + await Future.wait(>[slow, fast]); + + final Map byUrl = { + for (final HttpRequestRecord r in TelescopeStore.recentHttp()) + Uri.parse(r.url).path: r, + }; + expect(byUrl.keys, unorderedEquals(['/slow', '/fast'])); + expect(byUrl['/slow']!.durationMs, greaterThanOrEqualTo(350)); + expect(byUrl['/fast']!.durationMs, lessThan(350)); + expect(byUrl['/slow']!.attributedHeuristically, isFalse); + expect(byUrl['/slow']!.requestId, isNotNull); + expect(byUrl['/slow']!.requestId, isNot(byUrl['/fast']!.requestId)); + expect( + byUrl['/slow']!.endUs! - byUrl['/slow']!.startUs!, + greaterThanOrEqualTo(350000), + ); + expect(adapter.pendingCount, 0); + }); + + test('a request fired inside an interaction zone carries its id', () async { + final DioNetworkDriver driver = DioNetworkDriver( + baseUrl: 'http://127.0.0.1:${server.port}', + ); + Magic.bind('network', () => driver); + MagicHttpFacadeAdapter().install(); + final _FakeInteraction tap = _FakeInteraction('i3'); + _useFakeInteractions(); + + await _inInteraction(tap, () => driver.get('/fast')); + + final HttpRequestRecord record = TelescopeStore.recentHttp().single; + expect(record.interactionId, 'i3'); + expect(record.linkedBy, 'zone'); + }); + }); + + group('interaction links on records', () { + setUp(() { + MagicApp.reset(); + Magic.flush(); + MagicRouter.reset(); + EventDispatcher.instance.clear(); + TelescopeStore.resetForTesting(); + MagicPerfIntegration.resetForTesting(); + }); + + tearDown(() { + EventDispatcher.instance.clear(); + TelescopeStore.resetForTesting(); + MagicPerfIntegration.resetForTesting(); + MagicRouter.reset(); + }); + + test('a QueryExecuted fired inside an open interaction zone is linked by ' + 'zone, even while another interaction is active', () async { + MagicQueryWatcher().install(); + final _FakeInteraction tap = _FakeInteraction('i7'); + _useFakeInteractions(active: _FakeInteraction('i8')); + + await _inInteraction( + tap, + () => EventDispatcher.instance.dispatch( + QueryExecuted(sql: 'select 1', bindings: [], timeMs: 2), + ), + ); + + final QueryRecord record = TelescopeStore.recentQueries().single; + expect(record.interactionId, 'i7'); + expect(record.linkedBy, 'zone'); + }); + + test('a closed zone handle is absent: the active slot links by frame, ' + 'and with neither the record is linked by window', () async { + MagicModelWatcher().install(); + MagicCacheWatcher().install(); + MagicEventWatcher().install(); + final _FakeInteraction closed = _FakeInteraction('i1')..open = false; + final _FakeInteraction active = _FakeInteraction('i2'); + _useFakeInteractions(active: active); + + await _inInteraction( + closed, + () => EventDispatcher.instance.dispatch(CacheHit('k', 1)), + ); + active.open = false; + await EventDispatcher.instance.dispatch(AuthLogout(null)); + + final MagicCacheRecord cache = TelescopeStore.recentCaches().single; + expect(cache.interactionId, 'i2'); + expect(cache.linkedBy, 'frame'); + final EventRecord event = TelescopeStore.recentEvents().single; + expect(event.interactionId, isNull); + expect(event.linkedBy, 'window'); + }); + + testWidgets('a tap that navigates links by zone, and the next page\'s ' + 'initState refetch links by frame to the same interaction', ( + WidgetTester tester, + ) async { + MagicQueryWatcher().install(); + final _FakeInteraction tap = _FakeInteraction('i4'); + _useFakeInteractions(active: tap); + + MagicRoute.page( + '/', + () => Scaffold( + body: GestureDetector( + onTap: () { + EventDispatcher.instance.dispatch( + QueryExecuted( + sql: 'select * from here', + bindings: [], + timeMs: 1, + ), + ); + MagicRouter.instance.to('/next'); + }, + child: const Text('go'), + ), + ), + ); + MagicRoute.page('/next', () => const _NextPage()); + await tester.pumpWidget( + MaterialApp.router(routerConfig: MagicRouter.instance.routerConfig), + ); + await tester.pumpAndSettle(); + + // Dispatched the way dusk dispatches a gesture: inside the zone. The + // pumps that build the next page run in the test's own zone, as frames + // run in the binding's frame zone in an app. + await _inInteraction(tap, () => tester.tap(find.text('go'))); + await tester.pumpAndSettle(); + + expect(find.text('next'), findsOneWidget); + final Map bySql = { + for (final QueryRecord r in TelescopeStore.recentQueries()) r.sql: r, + }; + expect(bySql['select * from here']!.interactionId, 'i4'); + expect(bySql['select * from here']!.linkedBy, 'zone'); + expect(bySql['select * from next']!.interactionId, 'i4'); + expect(bySql['select * from next']!.linkedBy, 'frame'); + }); + }); + + group('HTTP credential redaction', () { + late HttpServer server; + HttpOverrides? bindingOverrides; + Object? received; + + setUp(() async { + // A testWidgets case in this file installs an HttpClient override that + // answers every request 400; these cases need the real loopback socket. + bindingOverrides = HttpOverrides.current; + HttpOverrides.global = null; + MagicApp.reset(); + Magic.flush(); + Log.fake(); + Vault.fake(); + Magic.singleton('auth', AuthManager.new); + // AuthManager caches its guards process-wide; a token stored by one + // test would otherwise ride along on the next. + Auth.manager.forgetGuards(); + TelescopeStore.resetForTesting(); + MagicTelescopeIntegration.resetForTesting(); + MagicPerfIntegration.resetForTesting(); + received = null; + + server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); + server.listen((HttpRequest request) async { + received = jsonDecode(await utf8.decoder.bind(request).join()); + request.response + ..statusCode = 200 + ..headers.contentType = ContentType.json + ..write('{"data":{"token":"sanctum-token","user":{"id":1}}}'); + await request.response.close(); + }); + }); + + tearDown(() async { + await server.close(force: true); + HttpOverrides.global = bindingOverrides; + Config.set('auth', {}); + Vault.unfake(); + Log.unfake(); + TelescopeStore.resetForTesting(); + MagicTelescopeIntegration.resetForTesting(); + MagicPerfIntegration.resetForTesting(); + MagicApp.reset(); + Magic.flush(); + }); + + /// Signs in with `sanctum-token` and posts a login body through a driver + /// that carries magic's own AuthInterceptor ahead of telescope's, the + /// order an app boots them in. + Future login() async { + final DioNetworkDriver driver = DioNetworkDriver( + baseUrl: 'http://127.0.0.1:${server.port}', + )..addInterceptor(AuthInterceptor()); + Magic.singleton('network', () => driver); + MagicTelescopeIntegration.install(); + await (Auth.guard() as BaseGuard).storeToken('sanctum-token'); + + await driver.post( + '/login', + data: {'email': 'a@b.test', 'password': 'hunter2'}, + ); + + return TelescopeStore.recentHttp().single; + } + + String? header(HttpRequestRecord record, String name) => record + .requestHeaders + ?.entries + .firstWhere( + (MapEntry entry) => + entry.key.toLowerCase() == name.toLowerCase(), + ) + .value; + + test('a login stores neither the password, the token nor the bearer ' + 'header, and the server still receives the real body', () async { + final HttpRequestRecord record = await login(); + + expect( + received, + equals({'email': 'a@b.test', 'password': 'hunter2'}), + ); + expect(header(record, 'Authorization'), equals('********')); + expect(record.requestBody, contains('a@b.test')); + final String stored = jsonEncode(record.toJson()); + expect(stored, isNot(contains('hunter2'))); + expect(stored, isNot(contains('sanctum-token'))); + }); + + test('the header auth.token.header names is masked too', () async { + Config.set('auth.token.header', 'X-Auth'); + + final HttpRequestRecord record = await login(); + + expect(header(record, 'X-Auth'), equals('********')); + expect(jsonEncode(record.toJson()), isNot(contains('sanctum-token'))); + expect(TelescopeRedaction.hiddenRequestHeaders, contains('x-auth')); + }); + + test('an error answer is masked with the response list, and the request ' + 'body the driver sends on is left untouched', () { + final _CapturingNetworkDriver driver = _CapturingNetworkDriver(); + Magic.bind('network', () => driver); + MagicHttpFacadeAdapter().install(); + final MagicNetworkInterceptor interceptor = driver.interceptors.single; + final Map body = { + 'password': 'hunter2', + }; + + interceptor.onRequest( + MagicRequest(url: '/login', method: 'POST', data: body, id: 1), + ); + interceptor.onError( + MagicError( + response: MagicResponse( + data: { + 'data': {'token': 't0k'}, + }, + statusCode: 500, + id: 1, + ), + ), + ); + + expect(body['password'], equals('hunter2')); + final HttpRequestRecord record = TelescopeStore.recentHttp().single; + expect(record.requestBody, isNot(contains('hunter2'))); + expect(record.responseBody, isNot(contains('t0k'))); + expect(record.responseBody, contains('********')); + }); + + test('a JSON string body is masked before it is cut to size', () { + final _CapturingNetworkDriver driver = _CapturingNetworkDriver(); + Magic.bind('network', () => driver); + MagicHttpFacadeAdapter().install(); + final MagicNetworkInterceptor interceptor = driver.interceptors.single; + + interceptor.onRequest( + MagicRequest( + url: '/login', + method: 'POST', + data: jsonEncode({ + 'password': 'hunter2', + 'padding': 'x' * 9000, + }), + id: 1, + ), + ); + interceptor.onResponse( + MagicResponse( + data: '{"token":"t0k","padding":"${'x' * 9000}"}', + statusCode: 200, + id: 1, + ), + ); + + final HttpRequestRecord record = TelescopeStore.recentHttp().single; + expect(record.requestBody, contains('[truncated')); + expect(record.requestBody, isNot(contains('hunter2'))); + expect(record.responseBody, isNot(contains('t0k'))); + }); + + test('install() hides the auth header again after the store was reset', () { + Config.set('auth.token.header', 'X-Auth'); + MagicTelescopeIntegration.install(); + + TelescopeStore.resetForTesting(); + MagicTelescopeIntegration.install(); + + expect(TelescopeRedaction.hiddenRequestHeaders, contains('x-auth')); + }); + }); }