From 9f097f59f681bc83b99e43a6fa85810c89be2bd5 Mon Sep 17 00:00:00 2001 From: Felix Delval Date: Fri, 25 Sep 2026 10:18:33 +0200 Subject: [PATCH 1/3] feat(core): add namespaced, runtime-toggleable trace channels MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Several investigations into extension-loading/RPC-timing bugs (SITES-48958, SITES-49454, and the Universal Editor extension-loading-timeout work) each independently hand-rolled the same throwaway tracing: an unconditional console.log, gated by a flag re-checked or re-parsed per call, formatted by hand at every call site. That last part caused the same bug three times -- passing an object as a second console.log argument collapses to unreadable `Array(N)`/`[{…}]` placeholders in a plain-text devtools export, so every investigation had to rediscover and fix that convention for itself. createTracer(namespace) centralizes this: - enabled is a live getter (cheap property read, no re-parsing), so a disabled tracer costs one function call + one property read + one typeof check -- no string building, no object allocation, no JSON.stringify. - details may be a function; it's only invoked while the namespace is enabled, so building it (mapping a guest list, serializing an error) never happens on the hot disabled path. - Formatting (inline JSON.stringify into the log message, with a timestamp) is owned by the tracer itself, not the call site -- the collapsing-object mistake becomes structurally impossible instead of a convention to remember. window.__UIX_DEBUG__ exposes enable(pattern)/disable()/list() at runtime -- query param (?uixDebug=...) or localStorage ("uix:debug") for persistence across reloads, exact/wildcard/"*" pattern matching, live against whichever tracers exist at call time (so enable("*") also covers tracers created afterward, regardless of module load order). Co-Authored-By: Claude Sonnet 5 --- packages/uix-core/src/index.ts | 1 + packages/uix-core/src/trace.test.ts | 151 +++++++++++++++++++++++++ packages/uix-core/src/trace.ts | 167 ++++++++++++++++++++++++++++ 3 files changed, 319 insertions(+) create mode 100644 packages/uix-core/src/trace.test.ts create mode 100644 packages/uix-core/src/trace.ts diff --git a/packages/uix-core/src/index.ts b/packages/uix-core/src/index.ts index 86aea7e1..5d779649 100644 --- a/packages/uix-core/src/index.ts +++ b/packages/uix-core/src/index.ts @@ -23,5 +23,6 @@ export * from "./types"; export * from "./cross-realm-object"; export * from "./logging-formatters"; export * from "./promises"; +export * from "./trace"; export * from "./tunnel"; export type { Asynced } from "./object-walker"; diff --git a/packages/uix-core/src/trace.test.ts b/packages/uix-core/src/trace.test.ts new file mode 100644 index 00000000..b208f39e --- /dev/null +++ b/packages/uix-core/src/trace.test.ts @@ -0,0 +1,151 @@ +/* +Copyright 2026 Adobe. All rights reserved. +This file is licensed to you under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. You may obtain a copy +of the License at http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software distributed under +the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR REPRESENTATIONS +OF ANY KIND, either express or implied. See the License for the specific language +governing permissions and limitations under the License. +*/ + +import { createTracer, __resetTraceStateForTests } from "./trace"; + +describe("createTracer", () => { + let logSpy: jest.SpyInstance; + + beforeEach(() => { + window.localStorage.clear(); + __resetTraceStateForTests(); + logSpy = jest.spyOn(console, "log").mockImplementation(() => undefined); + }); + + afterEach(() => { + logSpy.mockRestore(); + window.__UIX_DEBUG__?.disable(); + }); + + it("is disabled by default and logs nothing", () => { + const trace = createTracer("uix-host"); + + expect(trace.enabled).toBe(false); + trace("something happened"); + + expect(logSpy).not.toHaveBeenCalled(); + }); + + it("never calls a details thunk while disabled", () => { + const trace = createTracer("uix-host"); + const buildDetails = jest.fn(() => ({ expensive: "work" })); + + trace("something happened", buildDetails); + + expect(buildDetails).not.toHaveBeenCalled(); + }); + + it("logs a single JSON-structured line once its exact namespace is enabled", () => { + const trace = createTracer("uix-host"); + + window.__UIX_DEBUG__?.enable("uix-host"); + expect(trace.enabled).toBe(true); + + trace("guest connected", { id: "msm" }); + + expect(logSpy).toHaveBeenCalledTimes(1); + const [line] = logSpy.mock.calls[0] as [string]; + expect(line).toMatch(/^\[uix-host\] guest connected \{.*\}$/); + const payload = JSON.parse( + line.replace(/^\[uix-host\] guest connected /, "") + ) as Record; + expect(payload).toMatchObject({ id: "msm" }); + expect(payload.at).toEqual(expect.any(String)); + }); + + it("calls a details thunk once enabled, and uses its return value", () => { + const trace = createTracer("uix-host"); + window.__UIX_DEBUG__?.enable("uix-host"); + + trace("guest connected", () => ({ id: "msm" })); + + const [line] = logSpy.mock.calls[0] as [string]; + expect( + JSON.parse(line.replace(/^\[uix-host\] guest connected /, "")) + ).toMatchObject({ id: "msm" }); + }); + + it("does not enable other namespaces when enabling one by exact name", () => { + const hostTrace = createTracer("uix-host"); + const guestTrace = createTracer("uix-guest"); + + window.__UIX_DEBUG__?.enable("uix-host"); + + expect(hostTrace.enabled).toBe(true); + expect(guestTrace.enabled).toBe(false); + }); + + it("supports trailing-wildcard patterns", () => { + const hostTrace = createTracer("uix-host"); + const guestTrace = createTracer("uix-guest"); + const otherTrace = createTracer("rte-before-load"); + + window.__UIX_DEBUG__?.enable("uix-*"); + + expect(hostTrace.enabled).toBe(true); + expect(guestTrace.enabled).toBe(true); + expect(otherTrace.enabled).toBe(false); + }); + + it("'*' enables every namespace, including ones registered afterward", () => { + const hostTrace = createTracer("uix-host"); + + window.__UIX_DEBUG__?.enable("*"); + expect(hostTrace.enabled).toBe(true); + + // A tracer created after enable("*") should also come up enabled -- the + // check is live against the current pattern set, not baked in at + // createTracer() time. + const laterTrace = createTracer("some-new-namespace"); + expect(laterTrace.enabled).toBe(true); + }); + + it("enable() defaults to '*' when called with no pattern", () => { + const trace = createTracer("uix-host"); + + window.__UIX_DEBUG__?.enable(); + + expect(trace.enabled).toBe(true); + }); + + it("disable() turns every namespace back off and clears the persisted preference", () => { + const trace = createTracer("uix-host"); + window.__UIX_DEBUG__?.enable("uix-host"); + expect(trace.enabled).toBe(true); + + window.__UIX_DEBUG__?.disable(); + + expect(trace.enabled).toBe(false); + expect(window.localStorage.getItem("uix:debug")).toBeNull(); + }); + + it("list() returns every namespace a tracer has been created for, regardless of enabled state", () => { + createTracer("uix-host"); + createTracer("uix-guest"); + + expect(window.__UIX_DEBUG__?.list()).toEqual(["uix-guest", "uix-host"]); + }); + + it("persists enabled patterns to localStorage and a fresh page load honours them", () => { + const trace = createTracer("uix-host"); + window.__UIX_DEBUG__?.enable("uix-host"); + + expect(window.localStorage.getItem("uix:debug")).toBe("uix-host"); + + // Simulate a reload: reset in-memory state, but leave localStorage as-is. + __resetTraceStateForTests(); + const traceAfterReload = createTracer("uix-host"); + + expect(traceAfterReload.enabled).toBe(true); + void trace; // keep referenced for clarity of the "before" state above + }); +}); diff --git a/packages/uix-core/src/trace.ts b/packages/uix-core/src/trace.ts new file mode 100644 index 00000000..5f70155b --- /dev/null +++ b/packages/uix-core/src/trace.ts @@ -0,0 +1,167 @@ +/* +Copyright 2026 Adobe. All rights reserved. +This file is licensed to you under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. You may obtain a copy +of the License at http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software distributed under +the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR REPRESENTATIONS +OF ANY KIND, either express or implied. See the License for the specific language +governing permissions and limitations under the License. +*/ + +/** + * Namespaced, runtime-toggleable tracing for diagnosing extension-loading and + * RPC timing issues, in the SDK itself and in apps that consume it. + * + * Unlike {@link debugEmitter}/{@link _customConsole} (which require a `debug` + * option at construction time and produce human-oriented colored console + * output), a trace channel can be enabled *after the fact*, at runtime, by + * anyone with devtools access -- `__UIX_DEBUG__.enable("uix-host")` -- and + * produces single-line, JSON-structured output that survives a plain-text + * devtools console export. + * + * @packageDocumentation + */ + +/** A plain object of details to attach to a trace line. */ +type TraceDetails = Record; + +/** + * A namespaced trace function. Calling it is a no-op unless its namespace is + * currently enabled, in which case it logs `[namespace] label {...details}` + * with an ISO timestamp. + * + * `details` may be a plain object or a function returning one. Prefer a + * function whenever building `details` costs more than a property read or + * two (mapping a list, serializing an error) -- it will not be called at all + * while the namespace is disabled. + */ +export interface Tracer { + (label: string, details?: TraceDetails | (() => TraceDetails)): void; + /** Whether this tracer's namespace is currently enabled. Safe to check before doing any work the tracer itself doesn't need. */ + readonly enabled: boolean; +} + +/** Methods for enabling/inspecting trace channels at runtime, exposed as `window.__UIX_DEBUG__`. */ +export interface UixDebug { + /** + * Enable one or more namespace patterns. Patterns may be an exact + * namespace (`"uix-host"`), a trailing wildcard (`"uix-*"`), or `"*"` for + * everything. Persists across reloads via `localStorage`. + */ + enable(pattern?: string): void; + /** Disable all tracing and clear the persisted preference. */ + disable(): void; + /** Every namespace any tracer has been created for so far, enabled or not. */ + list(): string[]; +} + +const STORAGE_KEY = "uix:debug"; + +function readInitialPatterns(): string[] { + if (typeof window === "undefined") { + return []; + } + const fromQuery = new URLSearchParams(window.location?.search ?? "").get( + "uixDebug" + ); + const fromStorage = (() => { + try { + return window.localStorage?.getItem(STORAGE_KEY); + } catch { + // localStorage can throw in sandboxed/private contexts; treat as unset. + return null; + } + })(); + const raw = fromQuery ?? fromStorage ?? ""; + return raw + .split(",") + .map((pattern) => pattern.trim()) + .filter((pattern) => pattern.length > 0); +} + +let enabledPatterns: string[] = readInitialPatterns(); +const registry = new Set(); + +function matches(pattern: string, namespace: string): boolean { + if (pattern === "*" || pattern === namespace) { + return true; + } + return pattern.endsWith("*") && namespace.startsWith(pattern.slice(0, -1)); +} + +function isNamespaceEnabled(namespace: string): boolean { + return enabledPatterns.some((pattern) => matches(pattern, namespace)); +} + +/** + * Create a trace function for the given namespace. Cheap to call at module + * load time from anywhere -- registration itself has no cost, and the + * returned function does no work beyond a property read while its namespace + * is disabled. + */ +export function createTracer(namespace: string): Tracer { + registry.add(namespace); + + const tracer = (( + label: string, + details?: TraceDetails | (() => TraceDetails) + ) => { + if (!isNamespaceEnabled(namespace)) { + return; + } + const resolved = typeof details === "function" ? details() : details; + // eslint-disable-next-line no-console + console.log( + `[${namespace}] ${label} ${JSON.stringify({ + at: new Date().toISOString(), + ...resolved, + })}` + ); + }) as Tracer; + + Object.defineProperty(tracer, "enabled", { + get: () => isNamespaceEnabled(namespace), + }); + + return tracer; +} + +const uixDebug: UixDebug = { + disable(): void { + enabledPatterns = []; + try { + window.localStorage?.removeItem(STORAGE_KEY); + } catch { + // ignore -- localStorage unavailable + } + }, + enable(pattern = "*"): void { + enabledPatterns = [...new Set([...enabledPatterns, pattern])]; + try { + window.localStorage?.setItem(STORAGE_KEY, enabledPatterns.join(",")); + } catch { + // ignore -- localStorage unavailable + } + }, + list(): string[] { + return [...registry].sort(); + }, +}; + +declare global { + interface Window { + __UIX_DEBUG__?: UixDebug; + } +} + +if (typeof window !== "undefined") { + window.__UIX_DEBUG__ = uixDebug; +} + +/** @internal exported for tests only */ +export const __resetTraceStateForTests = (): void => { + enabledPatterns = readInitialPatterns(); + registry.clear(); +}; From 02b01b86d9d05e38eaba5307ba6321a22a000bfb Mon Sep 17 00:00:00 2001 From: Felix Delval Date: Fri, 25 Sep 2026 10:18:42 +0200 Subject: [PATCH 2/3] feat: instrument Host/Port/Guest RPC and load-batch timing with trace channels Wires createTracer into the three spots that took a multi-hour vendored-tarball detour to instrument ad-hoc in the last two investigations: - Host.addLoadsNewGuests/loadOneGuest (uix-host namespace): batch start/settle with the guest-id list, and per-guest connect start/succeeded/failed with duration -- answers "which guest is slow or broken, and how long does the whole batch take." - Port.invokeHostMethod (uix-host namespace): logs every call along with which host-api namespaces are currently registered for that guest, and whether it succeeded or threw (including the async case, via a non-blocking .then/.catch purely for tracing -- behavior is unchanged). This is what previously surfaced "host. has no property X" errors caused by Api.ts's updateOn: "all" batch-gating bug. - Guest.invokeChecker (uix-guest namespace): the unbounded 500ms retry loop wrapping every guest->host call, with a per-call id and attempt counter -- answers "how many times did this retry, and for how long." None of this runs unless a consuming app (or someone in devtools) calls __UIX_DEBUG__.enable("uix-host,uix-guest"). No behavior change when disabled. Co-Authored-By: Claude Sonnet 5 --- packages/uix-guest/src/guest.ts | 25 +++++++++- packages/uix-host/src/host.ts | 29 ++++++++++- packages/uix-host/src/port.ts | 85 ++++++++++++++++++++++++--------- 3 files changed, 114 insertions(+), 25 deletions(-) diff --git a/packages/uix-guest/src/guest.ts b/packages/uix-guest/src/guest.ts index 9302c580..b26ad4c0 100644 --- a/packages/uix-guest/src/guest.ts +++ b/packages/uix-guest/src/guest.ts @@ -21,6 +21,7 @@ import type { GuestApis, } from "@adobe/uix-core"; import { + createTracer, Emitter, formatHostMethodAddress, makeNamespaceProxy, @@ -30,6 +31,8 @@ import { } from "@adobe/uix-core"; import { debugGuest } from "./debug-guest.js"; +const trace = createTracer("uix-guest"); + /** * @public */ @@ -223,14 +226,32 @@ export class Guest< */ private async invokeChecker( invoker: RemoteMethodInvoker, - address: HostMethodAddress + address: HostMethodAddress, + attempt = 0, + callId = trace.enabled ? Math.random().toString(36).slice(2, 8) : "" ): Promise { + trace("invokeChecker attempt", () => ({ + address: formatHostMethodAddress(address), + attempt, + callId, + })); try { const res = await invoker(address); + trace("invokeChecker succeeded", () => ({ + address: formatHostMethodAddress(address), + attempt, + callId, + })); return new Promise((resolve) => resolve(res)); } catch (e) { + trace("invokeChecker failed, retrying in 500ms", () => ({ + address: formatHostMethodAddress(address), + attempt, + callId, + error: e instanceof Error ? e.message : String(e), + })); await new Promise((resolve) => setTimeout(resolve, 500)); - return this.invokeChecker(invoker, address); + return this.invokeChecker(invoker, address, attempt + 1, callId); } } diff --git a/packages/uix-host/src/host.ts b/packages/uix-host/src/host.ts index d81116c6..1718d564 100644 --- a/packages/uix-host/src/host.ts +++ b/packages/uix-host/src/host.ts @@ -18,12 +18,14 @@ import type { GuestApis, } from "@adobe/uix-core"; import type { CapabilitySpec } from "./port.js"; -import { Emitter, quietConsole } from "@adobe/uix-core"; +import { createTracer, Emitter, quietConsole } from "@adobe/uix-core"; import { Port, PortOptions } from "./port.js"; import { debugHost } from "./debug-host.js"; import { addMetrics } from "./metrics.js"; import { compareExtensions } from "./utils/compareExtensions.js"; +const trace = createTracer("uix-host"); + /** * Dictionary of {@link Port} objects by extension ID. * @public @@ -395,6 +397,12 @@ export class Host extends Emitter { ): Promise { const failed: Port[] = []; const loaded: Port[] = []; + const batchIds = Object.keys(extensions); + trace("addLoadsNewGuests batch start", () => ({ + batchIds, + count: batchIds.length, + hostName: this.hostName, + })); this.loading = true; await Promise.all( Object.entries(extensions).map(async ([id, extension]) => { @@ -403,6 +411,11 @@ export class Host extends Emitter { }) ); this.loading = false; + trace("addLoadsNewGuests batch settled", () => ({ + failedIds: failed.map((port) => port.id), + hostName: this.hostName, + loadedIds: loaded.map((port) => port.id), + })); this.emit("loadallguests", { host: this, failed, loaded }); } @@ -481,6 +494,11 @@ export class Host extends Emitter { this.guests.set(id, guest); } this.emit("guestbeforeload", { guest, host: this }); + const loadStart = Date.now(); + trace("loadOneGuest connect start", () => ({ + id, + url: guest.url?.toString(), + })); try { await guest.load(); } catch (e: unknown) { @@ -489,9 +507,18 @@ export class Host extends Emitter { e instanceof Error ? e.stack : String(e) }` ); + trace("loadOneGuest connect failed", () => ({ + durationMs: Date.now() - loadStart, + error: e instanceof Error ? e.message : String(e), + id, + })); this.emit("error", { host: this, guest, error }); return guest; } + trace("loadOneGuest connect succeeded", () => ({ + durationMs: Date.now() - loadStart, + id, + })); // this new guest might have new capabilities, so the identities of the // cached capability sets will need to change, to alert subscribers this.cachedCapabilityLists = new WeakMap(); diff --git a/packages/uix-host/src/port.ts b/packages/uix-host/src/port.ts index 24ed0d25..f35f0878 100644 --- a/packages/uix-host/src/port.ts +++ b/packages/uix-host/src/port.ts @@ -22,10 +22,12 @@ import type { UIHostMethods, GuestMetadata, } from "@adobe/uix-core"; -import { Emitter, connectIframe } from "@adobe/uix-core"; +import { createTracer, Emitter, connectIframe } from "@adobe/uix-core"; import { normalizeIframe } from "./dom-utils"; import { compareVersions } from "./utils/comparePackagesVersions"; +const trace = createTracer("uix-host"); + /** * A specifier for methods to be expected on a remote interface. * @@ -589,29 +591,68 @@ export class Port privateMethods?: VirtualApi ): T { const { name, path, args = [] } = address; - this.assert(name && typeof name === "string", () => "Method name required"); - this.assert( - path.length > 0, - () => - `Cannot call a method directly on the host; ".${name}()" must be in a namespace.` - ); - let methodCallee; - if (privateMethods) { - try { - methodCallee = this.getHostMethodCallee(address, privateMethods); - } catch (e) { - // private method not found, continue and try other way of accessing it + trace("invokeHostMethod called", () => ({ + guestId: this.id, + hasHostApisForPath: + path.length > 0 ? path[0] in this.hostApis : undefined, + hostApiNamespaces: Object.keys(this.hostApis), + name, + path, + })); + try { + this.assert( + name && typeof name === "string", + () => "Method name required" + ); + this.assert( + path.length > 0, + () => + `Cannot call a method directly on the host; ".${name}()" must be in a namespace.` + ); + let methodCallee; + if (privateMethods) { + try { + methodCallee = this.getHostMethodCallee(address, privateMethods); + } catch (e) { + // private method not found, continue and try other way of accessing it + } } + if (!methodCallee) { + methodCallee = this.getHostMethodCallee(address, this.hostApis); + } + const method = methodCallee[name] as (...args: unknown[]) => T; + this.emit("beforecallhostmethod", { guestPort: this, name, path, args }); + const result = method.apply(methodCallee, [ + { id: this.id, url: this.url }, + ...args, + ]) as T; + if (trace.enabled && result instanceof Promise) { + result.then( + () => + trace("invokeHostMethod succeeded", () => ({ + guestId: this.id, + name, + path, + })), + (error: unknown) => + trace("invokeHostMethod threw", () => ({ + error: error instanceof Error ? error.message : String(error), + guestId: this.id, + name, + path, + })) + ); + } + return result; + } catch (e: unknown) { + trace("invokeHostMethod threw", () => ({ + error: e instanceof Error ? e.message : String(e), + guestId: this.id, + name, + path, + })); + throw e; } - if (!methodCallee) { - methodCallee = this.getHostMethodCallee(address, this.hostApis); - } - const method = methodCallee[name] as (...args: unknown[]) => T; - this.emit("beforecallhostmethod", { guestPort: this, name, path, args }); - return method.apply(methodCallee, [ - { id: this.id, url: this.url }, - ...args, - ]) as T; } // #endregion Private Methods (6) From 435a3ec4d1c01c916acb18bdc674770687c2fbbc Mon Sep 17 00:00:00 2001 From: Felix Delval Date: Fri, 25 Sep 2026 10:38:24 +0200 Subject: [PATCH 3/3] test: cover the new uix-host/uix-guest trace channels Adds basic coverage that the wired-in tracing actually behaves as designed, at each of the three call sites from the previous commit: - host.test.ts (new -- no host.test.ts existed on main before this): Host.addLoadsNewGuests/loadOneGuest log batch start/settle and per-guest connect outcomes once uix-host is enabled, and log nothing otherwise (mocks Port entirely; real connection behavior is covered by port.test.ts). - port.test.ts: Port.invokeHostMethod logs the call plus which host-api namespaces are currently registered, and logs a throw when the requested namespace hasn't been provided -- the exact signature that surfaced the Api.ts updateOn: "all" bug in the extension-loading investigation. - guest.test.ts (new -- uix-guest had no wired-up jest project on main; added one alongside core/host/host-react): Guest.invokeChecker logs each attempt/success/failure with an incrementing attempt count and a callId held stable across the whole retry chain, and logs nothing while disabled. Every suite asserts the disabled case emits zero console.log calls -- the core "no behavior/perf impact when off" claim, verified rather than just documented. Co-Authored-By: Claude Sonnet 5 --- jest.config.ts | 11 ++- packages/uix-guest/src/guest.test.ts | 102 ++++++++++++++++++++++ packages/uix-host/src/host.test.ts | 123 +++++++++++++++++++++++++++ packages/uix-host/src/port.test.ts | 71 ++++++++++++++++ 4 files changed, 306 insertions(+), 1 deletion(-) create mode 100644 packages/uix-guest/src/guest.test.ts create mode 100644 packages/uix-host/src/host.test.ts diff --git a/jest.config.ts b/jest.config.ts index fa5445ab..73af46bd 100644 --- a/jest.config.ts +++ b/jest.config.ts @@ -31,7 +31,16 @@ const jestConfig = { "/packages/uix-core/src/__helpers__/jest.messagechannel.cjs", ], }), - sdkProject("host", {}), + sdkProject("host", { + moduleNameMapper: { + "^(\\.{1,2}/.*)\\.js$": "$1", + }, + }), + sdkProject("guest", { + moduleNameMapper: { + "^(\\.{1,2}/.*)\\.js$": "$1", + }, + }), sdkProject("host-react", { testMatch: [ "/packages/uix-host-react/src/**/*.test.ts", diff --git a/packages/uix-guest/src/guest.test.ts b/packages/uix-guest/src/guest.test.ts new file mode 100644 index 00000000..21d1bdf5 --- /dev/null +++ b/packages/uix-guest/src/guest.test.ts @@ -0,0 +1,102 @@ +import { Guest } from "./guest"; +import type { HostMethodAddress } from "@adobe/uix-core"; + +function createGuest() { + return new Guest({ id: "test-guest" }); +} + +const address: HostMethodAddress = { + args: [], + name: "get", + path: ["editorState"], +}; + +describe("Guest invokeChecker tracing", () => { + let logSpy: jest.SpyInstance; + + beforeEach(() => { + jest.useFakeTimers(); + logSpy = jest.spyOn(console, "log").mockImplementation(() => undefined); + }); + + afterEach(() => { + jest.useRealTimers(); + logSpy.mockRestore(); + window.__UIX_DEBUG__?.disable(); + }); + + it("logs nothing while the uix-guest namespace is disabled", async () => { + const guest = createGuest(); + const invoker = jest.fn().mockResolvedValue("value"); + + await (guest as any).invokeChecker(invoker, address); + + expect(logSpy).not.toHaveBeenCalled(); + }); + + it("logs a single attempt/succeeded pair for a call that resolves on the first try", async () => { + const guest = createGuest(); + const invoker = jest.fn().mockResolvedValue("value"); + window.__UIX_DEBUG__?.enable("uix-guest"); + + await (guest as any).invokeChecker(invoker, address); + + const lines = logSpy.mock.calls.map(([line]: [string]) => line); + expect( + lines.some( + (line) => + line.includes("invokeChecker attempt") && line.includes('"attempt":0') + ) + ).toBe(true); + expect( + lines.some( + (line) => + line.includes("invokeChecker succeeded") && + line.includes('"attempt":0') + ) + ).toBe(true); + }); + + it("logs a failed attempt and retries with an incrementing attempt count and stable callId", async () => { + const guest = createGuest(); + const invoker = jest + .fn() + .mockRejectedValueOnce(new Error("not ready")) + .mockResolvedValueOnce("value"); + window.__UIX_DEBUG__?.enable("uix-guest"); + + const resultPromise = (guest as any).invokeChecker( + invoker, + address + ) as Promise; + await jest.advanceTimersByTimeAsync(500); + const result = await resultPromise; + + expect(result).toBe("value"); + const lines = logSpy.mock.calls.map(([line]: [string]) => line); + + const failedLine = lines.find((line) => + line.includes("invokeChecker failed") + ); + expect(failedLine).toContain('"attempt":0'); + expect(failedLine).toContain("not ready"); + + const retryAttemptLine = lines.find( + (line) => + line.includes("invokeChecker attempt") && line.includes('"attempt":1') + ); + expect(retryAttemptLine).toBeDefined(); + + const succeededLine = lines.find((line) => + line.includes("invokeChecker succeeded") + ); + expect(succeededLine).toContain('"attempt":1'); + + // Every line for this call shares one callId, generated once at the top of the retry chain. + const callIds = new Set( + lines.map((line) => (line.match(/"callId":"(\w+)"/) ?? [])[1]) + ); + expect(callIds.size).toBe(1); + expect([...callIds][0]).toEqual(expect.stringMatching(/^[a-z0-9]+$/)); + }); +}); diff --git a/packages/uix-host/src/host.test.ts b/packages/uix-host/src/host.test.ts new file mode 100644 index 00000000..4b4c0f0d --- /dev/null +++ b/packages/uix-host/src/host.test.ts @@ -0,0 +1,123 @@ +import { Host } from "./host"; + +// Mock Port entirely -- these tests are about Host.addLoadsNewGuests/ +// loadOneGuest's tracing, not about real iframe connection behavior (which +// port.test.ts already covers). +const loadBehaviors = new Map Promise>(); + +jest.mock("./port", () => { + class MockPort { + id: string; + url: URL; + error?: Error; + + constructor(config: { id: string; url: URL }) { + this.id = config.id; + this.url = config.url; + } + + async load() { + const behavior = loadBehaviors.get(this.id); + try { + await behavior?.(); + } catch (e) { + this.error = e instanceof Error ? e : new Error(String(e)); + throw e; + } + } + } + return { Port: MockPort }; +}); + +function createHost() { + const container = document.createElement("div"); + document.body.appendChild(container); + return new Host({ hostName: "test-host", runtimeContainer: container }); +} + +describe("Host", () => { + let logSpy: jest.SpyInstance; + + beforeEach(() => { + loadBehaviors.clear(); + logSpy = jest.spyOn(console, "log").mockImplementation(() => undefined); + }); + + afterEach(() => { + logSpy.mockRestore(); + window.__UIX_DEBUG__?.disable(); + }); + + describe("uix-host tracing", () => { + it("logs nothing while the uix-host namespace is disabled", async () => { + loadBehaviors.set("working", async () => undefined); + const host = createHost(); + + await host.load({ working: "https://example.com/working" }); + + expect(logSpy).not.toHaveBeenCalled(); + }); + + it("logs batch start/settle and per-guest connect outcomes once enabled", async () => { + loadBehaviors.set("working", async () => undefined); + loadBehaviors.set("broken", async () => { + throw new Error("connect failed"); + }); + window.__UIX_DEBUG__?.enable("uix-host"); + const host = createHost(); + + await host.load({ + broken: "https://example.com/broken", + working: "https://example.com/working", + }); + + const lines = logSpy.mock.calls.map(([line]: [string]) => line); + + expect( + lines.some((line) => line.includes("addLoadsNewGuests batch start")) + ).toBe(true); + expect( + lines.some((line) => line.includes('"batchIds":["broken","working"]')) + ).toBe(true); + + expect( + lines.some( + (line) => + line.includes("loadOneGuest connect start") && + line.includes('"id":"working"') + ) + ).toBe(true); + expect( + lines.some( + (line) => + line.includes("loadOneGuest connect succeeded") && + line.includes('"id":"working"') + ) + ).toBe(true); + expect( + lines.some( + (line) => + line.includes("loadOneGuest connect failed") && + line.includes('"id":"broken"') && + line.includes("connect failed") + ) + ).toBe(true); + + const settled = lines.find((line) => + line.includes("addLoadsNewGuests batch settled") + ); + expect(settled).toContain('"failedIds":["broken"]'); + expect(settled).toContain('"loadedIds":["working"]'); + }); + + it("does not log for a namespace that was never enabled", async () => { + loadBehaviors.set("working", async () => undefined); + window.__UIX_DEBUG__?.enable("some-other-namespace"); + const host = createHost(); + + await host.load({ working: "https://example.com/working" }); + + expect(logSpy).not.toHaveBeenCalled(); + }); + }); +}); diff --git a/packages/uix-host/src/port.test.ts b/packages/uix-host/src/port.test.ts index 966761df..579627a3 100644 --- a/packages/uix-host/src/port.test.ts +++ b/packages/uix-host/src/port.test.ts @@ -138,4 +138,75 @@ describe("Port", () => { ); }); }); + + describe("invokeHostMethod tracing", () => { + let logSpy: jest.SpyInstance; + + beforeEach(() => { + logSpy = jest.spyOn(console, "log").mockImplementation(() => undefined); + }); + + afterEach(() => { + logSpy.mockRestore(); + window.__UIX_DEBUG__?.disable(); + }); + + it("logs nothing while the uix-host namespace is disabled", () => { + const { port } = createPort(); + port.provide({ editorState: { get: () => "value" } }); + + (port as any).invokeHostMethod({ + args: [], + name: "get", + path: ["editorState"], + }); + + expect(logSpy).not.toHaveBeenCalled(); + }); + + it("logs the call and which host-api namespaces are registered, once enabled", () => { + const { port } = createPort(); + port.provide({ editorState: { get: () => "value" } }); + window.__UIX_DEBUG__?.enable("uix-host"); + + (port as any).invokeHostMethod({ + args: [], + name: "get", + path: ["editorState"], + }); + + const [line] = logSpy.mock.calls[0] as [string]; + expect(line).toContain("invokeHostMethod called"); + expect(line).toContain('"hasHostApisForPath":true'); + expect(line).toContain('"hostApiNamespaces":["editorState"]'); + expect(line).toContain('"name":"get"'); + }); + + it("logs a throw when the requested namespace hasn't been provided yet", () => { + const { port } = createPort(); + window.__UIX_DEBUG__?.enable("uix-host"); + + expect(() => + (port as any).invokeHostMethod({ + args: [], + name: "get", + path: ["editorState"], + }) + ).toThrow(); + + const lines = (logSpy.mock.calls as [string][]).map(([line]) => line); + + const calledLine = lines.find((line) => + line.includes("invokeHostMethod called") + ); + expect(calledLine).toContain('"hasHostApisForPath":false'); + expect(calledLine).toContain('"hostApiNamespaces":[]'); + + const threwLine = lines.find((line) => + line.includes("invokeHostMethod threw") + ); + expect(threwLine).toContain("has no property"); + expect(threwLine).toContain("editorState"); + }); + }); });