diff --git a/src/Metrics/ScenarioMonitor.phaseOrdering.test.ts b/src/Metrics/ScenarioMonitor.phaseOrdering.test.ts new file mode 100644 index 000000000..21d2e00be --- /dev/null +++ b/src/Metrics/ScenarioMonitor.phaseOrdering.test.ts @@ -0,0 +1,152 @@ +/** + * @jest-environment jsdom + * + * Regression tests for IcM 865096261 — DataExplorerHealthV2 "High Unhealthy Percentage". + * + * Before the fix, ScenarioMonitor.completePhase() silently no-oped when the phase had not + * been started yet. The production call ordering in Explorer.tsx / ResourceTree.tsx always + * hits that case: + * + * - DatabaseTreeRendered is started at Explorer.tsx:451, but the effect that completes it + * (useMetricPhases.ts:55-59) last fires on the databaseTreeNodes change that happens + * *before* line 451. databaseTreeNodes is useMemo'd (ResourceTree.tsx:54), so the effect + * never re-fires and the phase stayed open until the 10 s timeout. + * - Interactive is completed by a one-shot effect (deps [scenario, enabled]) that can run + * before Explorer.tsx:577 starts the scenario at all. + * + * Telemetry over 3 days: DatabaseTreeRendered missing in 1624 of 1627 DatabaseLoad timeouts + * (99.8%), Interactive missing in 588. + * + * Line references are against 1f04f0ae. + */ + +import { updateUserContext } from "../UserContext"; +import MetricScenario, { reportMetric } from "./MetricEvents"; +import { ApplicationMetricPhase, CommonMetricPhase } from "./ScenarioConfig"; +import { scenarioMonitor } from "./ScenarioMonitor"; + +jest.mock("./MetricEvents", () => ({ + __esModule: true, + default: { + ApplicationLoad: "ApplicationLoad", + DatabaseLoad: "DatabaseLoad", + }, + reportMetric: jest.fn().mockResolvedValue({ ok: true }), +})); + +jest.mock("../ConfigContext", () => ({ + configContext: { + platform: "Portal", + PORTAL_BACKEND_ENDPOINT: "https://test.portal.azure.com", + }, + Platform: { Portal: "Portal", Hosted: "Hosted", Emulator: "Emulator", Fabric: "Fabric" }, +})); + +/** Stands in for the useDatabaseLoadScenario effect firing on a databaseTreeNodes change. */ +const treeRenderEffectFires = () => + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabaseTreeRendered); + +const lastEmit = () => (reportMetric as jest.Mock).mock.calls.at(-1)[0]; + +const ALL_DATABASE_LOAD_PHASES = [ + ApplicationMetricPhase.DatabasesFetched, + ApplicationMetricPhase.CollectionsLoaded, + ApplicationMetricPhase.DatabaseTreeRendered, + CommonMetricPhase.Interactive, +]; + +describe("DatabaseLoad phase ordering (IcM 865096261)", () => { + beforeEach(() => { + jest.clearAllMocks(); + jest.useFakeTimers({ legacyFakeTimers: true }); + updateUserContext({ apiType: "SQL" }); + scenarioMonitor.reset(); + }); + + afterEach(() => { + scenarioMonitor.reset(); + jest.useRealTimers(); + }); + + it("completes healthy under the production call ordering", () => { + // Explorer.tsx:577 — refreshExplorer starts the scenario + scenarioMonitor.start(MetricScenario.DatabaseLoad); + + // Explorer.tsx:336 — databases fetched + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabasesFetched); + + // ResourceTree re-renders (databases arrived) -> effect fires before the phase exists. + treeRenderEffectFires(); + + // Explorer.tsx:430 — _loadCollections begins + scenarioMonitor.startPhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.CollectionsLoaded); + + // Last databaseTreeNodes change; the memoised value never changes again after this. + treeRenderEffectFires(); + + // Explorer.tsx:449 / :451 — synchronous, immediately after `await Promise.all(...)` + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.CollectionsLoaded); + scenarioMonitor.startPhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabaseTreeRendered); + + // useInteractive rAF / 1 s fallback + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, CommonMetricPhase.Interactive); + + jest.advanceTimersByTime(10_000); + + const emitted = lastEmit(); + expect(emitted.scenario).toBe("DatabaseLoad"); + expect(emitted.timedOut).toBe(false); + expect(emitted.healthy).toBe(true); + expect(emitted.completedPhases).toEqual(expect.arrayContaining(ALL_DATABASE_LOAD_PHASES)); + }); + + it("honours a completion that arrives before the scenario is started", () => { + // ResourceTree mounts and its one-shot effects run before Explorer.tsx:577. + treeRenderEffectFires(); + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, CommonMetricPhase.Interactive); + + scenarioMonitor.start(MetricScenario.DatabaseLoad); + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabasesFetched); + scenarioMonitor.startPhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.CollectionsLoaded); + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.CollectionsLoaded); + scenarioMonitor.startPhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabaseTreeRendered); + + jest.advanceTimersByTime(10_000); + + const emitted = lastEmit(); + expect(emitted.timedOut).toBe(false); + expect(emitted.healthy).toBe(true); + expect(emitted.completedPhases).toEqual(expect.arrayContaining(ALL_DATABASE_LOAD_PHASES)); + }); + + it("still reports unhealthy when a phase genuinely never completes", () => { + scenarioMonitor.start(MetricScenario.DatabaseLoad); + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabasesFetched); + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, CommonMetricPhase.Interactive); + // CollectionsLoaded and DatabaseTreeRendered never arrive — a real stall. + + jest.advanceTimersByTime(10_000); + + const emitted = lastEmit(); + expect(emitted.timedOut).toBe(true); + expect(emitted.healthy).toBe(false); + expect(emitted.completedPhases).not.toContain(ApplicationMetricPhase.CollectionsLoaded); + }); + + it("does not count a timeout against health while the tab is backgrounded", () => { + const hidden = jest.spyOn(document, "hidden", "get").mockReturnValue(true); + try { + scenarioMonitor.start(MetricScenario.DatabaseLoad); + scenarioMonitor.completePhase(MetricScenario.DatabaseLoad, ApplicationMetricPhase.DatabasesFetched); + + jest.advanceTimersByTime(10_000); + + const emitted = lastEmit(); + expect(emitted.timedOut).toBe(true); + expect(emitted.documentHidden).toBe(true); + expect(emitted.healthy).toBe(true); + } finally { + hidden.mockRestore(); + } + }); +}); diff --git a/src/Metrics/ScenarioMonitor.ts b/src/Metrics/ScenarioMonitor.ts index c0fc28b2c..6d4982164 100644 --- a/src/Metrics/ScenarioMonitor.ts +++ b/src/Metrics/ScenarioMonitor.ts @@ -27,6 +27,9 @@ interface InternalScenarioContext { class ScenarioMonitor { private contexts = new Map(); + // Completions reported before start() created a context. Replayed on start() so that a + // React effect firing ahead of the scenario is not silently dropped. + private earlyCompletions = new Map>(); private vitals: WebVitals = {}; private vitalsInitialized = false; @@ -127,11 +130,21 @@ class ScenarioMonitor { hasExpectedFailure: ctx.hasExpectedFailure, }); - // If an expected failure occurred (auth, firewall, etc.), emit healthy instead of unhealthy - const healthy = ctx.hasExpectedFailure; + // Expected failures (auth, firewall, ...) are not our outage. Neither is a timeout in + // a backgrounded tab: browsers throttle timers and suspend rAF there, so phase + // completion is unreliable and the elapsed time is not the user's experience. + // documentHidden is still reported so these can be sliced out in telemetry. + const healthy = ctx.hasExpectedFailure || document.hidden; this.emit(ctx, healthy, true); }, config.timeoutMs); this.contexts.set(scenario, ctx); + + // Replay completions that were reported before this scenario existed. + const early = this.earlyCompletions.get(scenario); + if (early) { + this.earlyCompletions.delete(scenario); + early.forEach((phase) => this.completePhase(scenario, phase)); + } } startPhase(scenario: MetricScenario, phase: MetricPhase) { @@ -185,11 +198,36 @@ class ScenarioMonitor { completePhase(scenario: MetricScenario, phase: MetricPhase) { const ctx = this.contexts.get(scenario); - const phaseCtx = ctx?.phases.get(phase); - if (!ctx || ctx.emitted || ctx.completed.has(phase) || !ctx.config.requiredPhases.includes(phase) || !phaseCtx) { + + // The scenario has not been started yet. Remember the completion and replay it in + // start(); otherwise a one-shot React effect that fired early is lost forever. + if (!ctx) { + const config = scenarioConfigs[scenario]; + if (config?.requiredPhases.includes(phase)) { + const pending = this.earlyCompletions.get(scenario) ?? new Set(); + pending.add(phase); + this.earlyCompletions.set(scenario, pending); + this.devLog(`phase_complete_early: ${scenario}.${phase} — buffered until scenario start`); + } return; } + if (ctx.emitted || ctx.completed.has(phase) || !ctx.config.requiredPhases.includes(phase)) { + return; + } + + // The phase is required but has not been started yet (deferred phases are started + // explicitly, and the caller may run before that happens). Self-start it now so the + // completion is honoured instead of silently dropped. + let phaseCtx = ctx.phases.get(phase); + if (!phaseCtx) { + const lateStartMarkName = `scenario_${scenario}_${phase}_start`; + performance.mark(lateStartMarkName); + phaseCtx = { startMarkName: lateStartMarkName }; + ctx.phases.set(phase, phaseCtx); + this.devLog(`phase_autostart: ${scenario}.${phase} — completed before startPhase()`); + } + const endMarkName = `scenario_${scenario}_${phase}_end`; performance.mark(endMarkName); phaseCtx.endMarkName = endMarkName; @@ -446,6 +484,7 @@ class ScenarioMonitor { } }); this.contexts.clear(); + this.earlyCompletions.clear(); } } diff --git a/src/hooks/useKnockoutExplorer.ts b/src/hooks/useKnockoutExplorer.ts index 8b8c63a3a..119f603a3 100644 --- a/src/hooks/useKnockoutExplorer.ts +++ b/src/hooks/useKnockoutExplorer.ts @@ -108,7 +108,14 @@ export function useKnockoutExplorer(platform: Platform): Explorer { scenarioMonitor.completePhase(MetricScenario.ApplicationLoad, ApplicationMetricPhase.ExplorerInitialized); } }; - effect(); + effect().catch((error) => { + // configurePortal now rejects instead of hanging forever, so this is reachable. + // Without a handler it would surface only as an unhandled rejection. + Logger.logError( + error instanceof Error ? error.message : String(error), + "useKnockoutExplorer/configure", + ); + }); }, [platform]); useEffect(() => { @@ -705,6 +712,13 @@ export async function fetchAndUpdateKeys(subscriptionId: string, resourceGroup: } } +// The portal configures Data Explorer with a single iframe message. If a dependency on the +// portal side never resolves, that message is never posted — and without this timeout the +// promise below stays pending forever, leaving the user on with no +// diagnostic while the ApplicationLoad health scenario times out mute (IcM 865096261). +// Deliberately well above the 10s scenario budget so only genuinely stuck handshakes fail. +const PORTAL_INIT_MESSAGE_TIMEOUT_MS = 30000; + async function configurePortal(): Promise { const configureStartKey = traceStart(Action.ConfigurePortal, { dataExplorerArea: "ResourceTree", @@ -714,7 +728,9 @@ async function configurePortal(): Promise { }); let explorer: Explorer; - return new Promise((resolve) => { + let initMessageTimeoutId: number; + + const explorerReady = new Promise((resolve) => { // In development mode, try to load the iframe message from session storage. // This allows webpack hot reload to function properly in the portal if (process.env.NODE_ENV === "development" && !window.location.search.includes("disablePortalInitCache")) { @@ -849,6 +865,22 @@ async function configurePortal(): Promise { sendReadyMessage(); }); + + const initMessageTimeout = new Promise((_resolve, reject) => { + initMessageTimeoutId = window.setTimeout(() => { + const error = new Error( + `Portal did not send the Data Explorer init message within ${PORTAL_INIT_MESSAGE_TIMEOUT_MS}ms`, + ); + traceFailure(Action.ConfigurePortal, { error: error.message }, configureStartKey); + reject(error); + }, PORTAL_INIT_MESSAGE_TIMEOUT_MS); + }); + + try { + return await Promise.race([explorerReady, initMessageTimeout]); + } finally { + window.clearTimeout(initMessageTimeoutId); + } } function shouldForwardMessage(message: PortalMessage, messageOrigin: string) {