diff --git a/packages/fusion-runtime/src/executor.ts b/packages/fusion-runtime/src/executor.ts index 1580d00c2..672e12f76 100644 --- a/packages/fusion-runtime/src/executor.ts +++ b/packages/fusion-runtime/src/executor.ts @@ -8,7 +8,7 @@ import { type ExecutionResult, } from '@graphql-tools/utils'; import { DisposableSymbols } from '@whatwg-node/disposablestack'; -import type { DocumentNode } from 'graphql'; +import { print, type DocumentNode } from 'graphql'; import { UnifiedGraphManager, type UnifiedGraphManagerOptions, @@ -32,11 +32,16 @@ export function getExecutorForUnifiedGraph( (context) => { return mapMaybePromise( unifiedGraphManager.getUnifiedGraph(), - (unifiedGraph) => - createDefaultExecutor(unifiedGraph)({ + (unifiedGraph) => { + opts?.transportContext?.logger?.debug( + 'Executing request on unified graph', + print(execReq.document), + ); + return createDefaultExecutor(unifiedGraph)({ ...execReq, context, - }), + }); + }, ); }, ); @@ -46,6 +51,9 @@ export function getExecutorForUnifiedGraph( enumerable: true, get() { return function unifiedGraphExecutorDispose() { + opts?.transportContext?.logger?.debug( + 'Disposing unified graph executor', + ); return unifiedGraphManager[DisposableSymbols.asyncDispose](); }; }, diff --git a/packages/fusion-runtime/src/unifiedGraphManager.ts b/packages/fusion-runtime/src/unifiedGraphManager.ts index bb152e8af..edfa0d9cb 100644 --- a/packages/fusion-runtime/src/unifiedGraphManager.ts +++ b/packages/fusion-runtime/src/unifiedGraphManager.ts @@ -158,12 +158,16 @@ export class UnifiedGraphManager implements AsyncDisposable { this.lastLoadTime != null && Date.now() - this.lastLoadTime >= this.opts.pollingInterval ) { + this.opts?.transportContext?.logger?.debug(`Polling Supergraph`); this.polling$ = mapMaybePromise(this.getAndSetUnifiedGraph(), () => { this.polling$ = undefined; }); } if (!this.unifiedGraph) { if (!this.initialUnifiedGraph$) { + this.opts?.transportContext?.logger?.debug( + 'Fetching the initial Supergraph', + ); if (this.opts.transportContext?.cache) { this.opts.transportContext?.logger?.debug( `Searching for Supergraph in cache under key "${UNIFIEDGRAPH_CACHE_KEY}"...`, @@ -186,11 +190,18 @@ export class UnifiedGraphManager implements AsyncDisposable { } else { this.initialUnifiedGraph$ = this.getAndSetUnifiedGraph(); } + this.initialUnifiedGraph$ = mapMaybePromise( + this.initialUnifiedGraph$, + (v) => { + this.initialUnifiedGraph$ = undefined; + this.opts.transportContext?.logger?.debug( + 'Initial Supergraph fetched', + ); + return v; + }, + ); } - return mapMaybePromise(this.initialUnifiedGraph$, (v) => { - this.initialUnifiedGraph$ = undefined; - return v; - }); + return this.initialUnifiedGraph$ || this.unifiedGraph; } return this.unifiedGraph; } @@ -450,7 +461,10 @@ export class UnifiedGraphManager implements AsyncDisposable { public getUnifiedGraph(): MaybePromise { return mapMaybePromise(this.ensureUnifiedGraph(), () => { - return this.unifiedGraph!; + if (!this.unifiedGraph) { + throw new Error(`This should not happen!`); + } + return this.unifiedGraph; }); } diff --git a/packages/fusion-runtime/tests/polling.test.ts b/packages/fusion-runtime/tests/polling.test.ts index 99971c468..b2d5a169a 100644 --- a/packages/fusion-runtime/tests/polling.test.ts +++ b/packages/fusion-runtime/tests/polling.test.ts @@ -5,7 +5,7 @@ import { createDefaultExecutor, type DisposableExecutor, } from '@graphql-mesh/transport-common'; -import { makeDisposable } from '@graphql-mesh/utils'; +import { DefaultLogger, makeDisposable } from '@graphql-mesh/utils'; import { normalizedExecutor } from '@graphql-tools/executor'; import { createDeferred, @@ -299,7 +299,12 @@ describe('Polling', () => { expect(callTimes[1]?.toString()?.length).toBe(5); }, 20_000); it('does not block incoming requests while polling', async () => { - vi.useFakeTimers?.(); + // Jest's timer is acting weird + if (process.env['LEAK_TEST']) { + vi.useRealTimers?.(); + } else { + vi.useFakeTimers?.(); + } let schema: GraphQLSchema; let unifiedGraph: string; let graphDeferred: PromiseWithResolvers | undefined; @@ -326,16 +331,23 @@ describe('Polling', () => { return createdTime; } const firstCreatedTime = updateGraph(); - const unifiedGraphFetcher = vi.fn(() => - graphDeferred ? graphDeferred.promise : unifiedGraph, - ); + const unifiedGraphFetcher = vi.fn(() => { + return graphDeferred ? graphDeferred.promise : unifiedGraph; + }); + const logger = new DefaultLogger(); await using executor = getExecutorForUnifiedGraph({ getUnifiedGraph: unifiedGraphFetcher, pollingInterval: 10_000, + transportContext: { + logger, + }, transports() { + logger.debug('transports'); return { getSubgraphExecutor() { + logger.debug('getSubgraphExecutor'); return function dynamicExecutor(...args) { + logger.debug('dynamicExecutor'); return createDefaultExecutor(schema)(...args); }; }, @@ -356,7 +368,13 @@ describe('Polling', () => { }); expect(unifiedGraphFetcher).toHaveBeenCalledTimes(1); graphDeferred = createDeferred(); + const timeout$ = new Promise((resolve) => { + globalThis.setTimeout(() => { + resolve(); + }, 10_000); + }); await advanceTimersByTimeAsync(10_000); + await timeout$; const secondRes = await executor({ document: parse(/* GraphQL */ ` query {