From 597e7905e542be06e7f576d8ffde3f94d7b0630b Mon Sep 17 00:00:00 2001 From: Arda TANRIKULU Date: Thu, 25 Jul 2024 17:53:23 +0300 Subject: [PATCH] More verbose logging (#7343) * feat(utils): add timestamp to log messages * More * chore(dependencies): updated changesets for modified dependencies * Fix * chore(dependencies): updated changesets for modified dependencies * Simplify the API * Docs * .. * F * Improvements * Lazy logging * added some more logging --------- Co-authored-by: github-actions[bot] Co-authored-by: Dotan Simha --- .changeset/chilled-bees-lick.md | 5 +++ .changeset/curly-waves-obey.md | 6 +++ .changeset/fuzzy-trees-love.md | 12 ++++++ .changeset/quiet-mayflies-shave.md | 9 ++++ .changeset/rich-cougars-glow.md | 5 +++ .../fusion/runtime/src/unifiedGraphManager.ts | 6 +-- packages/fusion/runtime/src/utils.ts | 43 +++++++++++++++++-- packages/legacy/types/src/index.ts | 5 ++- packages/legacy/utils/src/logger.ts | 21 ++++++--- .../legacy/utils/src/wrapFetchWithHooks.ts | 34 ++++++++++++++- .../openapi/tests/example_api7.test.ts | 2 +- .../loaders/openapi/tests/file-upload.test.ts | 2 +- .../hmac-upstream-signature/src/index.ts | 27 +++++++++++- .../src/useHMACUpstreamSignature.spec.ts | 29 +++++-------- packages/plugins/jwt-auth/src/index.ts | 7 ++- packages/plugins/jwt-auth/src/useJWT.spec.ts | 12 +++--- .../prometheus/tests/prometheus.spec.ts | 2 +- .../serve-runtime/src/createServeRuntime.ts | 20 ++++++--- packages/serve-runtime/src/useFetchDebug.ts | 21 +++++++++ packages/serve-runtime/src/useRequestId.ts | 29 +++++++++++++ .../src/useSubgraphExecuteDebug.ts | 33 ++++++++++++++ .../serve-runtime/tests/serve-runtime.spec.ts | 18 ++++---- .../serve-runtime/tests/subscriptions.test.ts | 2 +- .../tests/useForwardHeaders.spec.ts | 23 +++++----- .../v1/serve/features/custom-plugins.mdx | 2 + 25 files changed, 301 insertions(+), 74 deletions(-) create mode 100644 .changeset/chilled-bees-lick.md create mode 100644 .changeset/curly-waves-obey.md create mode 100644 .changeset/fuzzy-trees-love.md create mode 100644 .changeset/quiet-mayflies-shave.md create mode 100644 .changeset/rich-cougars-glow.md create mode 100644 packages/serve-runtime/src/useFetchDebug.ts create mode 100644 packages/serve-runtime/src/useRequestId.ts create mode 100644 packages/serve-runtime/src/useSubgraphExecuteDebug.ts diff --git a/.changeset/chilled-bees-lick.md b/.changeset/chilled-bees-lick.md new file mode 100644 index 0000000000000..773d36f1687ca --- /dev/null +++ b/.changeset/chilled-bees-lick.md @@ -0,0 +1,5 @@ +--- +'@graphql-mesh/serve-runtime': patch +--- + +Fix the issue when you go to landing page then GraphiQL, queries are not executed diff --git a/.changeset/curly-waves-obey.md b/.changeset/curly-waves-obey.md new file mode 100644 index 0000000000000..46b3c94f2011d --- /dev/null +++ b/.changeset/curly-waves-obey.md @@ -0,0 +1,6 @@ +--- +'@graphql-mesh/fusion-runtime': patch +'@graphql-mesh/serve-runtime': patch +--- + +More verbose debug logs for HTTP fetch calls and subgraph requests diff --git a/.changeset/fuzzy-trees-love.md b/.changeset/fuzzy-trees-love.md new file mode 100644 index 0000000000000..4bd3bb4d48b66 --- /dev/null +++ b/.changeset/fuzzy-trees-love.md @@ -0,0 +1,12 @@ +--- +'@graphql-mesh/serve-runtime': patch +--- + +Request ID; + +If user provides a request id with `x-request-id` header, it will be used as a request id otherwise Mesh generates a random UUID as a request id. +Then it will return the request id in the response headers with `x-request-id` header. + +This `x-request-id` is also available in upstream headers as `request-id` for the upstream services to use. + +This request id will also be added to the logs. diff --git a/.changeset/quiet-mayflies-shave.md b/.changeset/quiet-mayflies-shave.md new file mode 100644 index 0000000000000..fe7ad14577e30 --- /dev/null +++ b/.changeset/quiet-mayflies-shave.md @@ -0,0 +1,9 @@ +--- +'@graphql-mesh/utils': patch +--- + +Add timestamp to log messages + +``` +[2021-09-29T14:00:00.000Z] XXXX +``` diff --git a/.changeset/rich-cougars-glow.md b/.changeset/rich-cougars-glow.md new file mode 100644 index 0000000000000..e472f38c15bbf --- /dev/null +++ b/.changeset/rich-cougars-glow.md @@ -0,0 +1,5 @@ +--- +'@graphql-mesh/utils': patch +--- + +Prevent logger to have the same log prefixes diff --git a/packages/fusion/runtime/src/unifiedGraphManager.ts b/packages/fusion/runtime/src/unifiedGraphManager.ts index 61842f98353b3..c1babd74b08c7 100644 --- a/packages/fusion/runtime/src/unifiedGraphManager.ts +++ b/packages/fusion/runtime/src/unifiedGraphManager.ts @@ -77,7 +77,7 @@ export class UnifiedGraphManager { private inContextSDK; private initialUnifiedGraph$: MaybePromise; private disposableStack = new AsyncDisposableStack(); - private _transportEntryMap: Record; + _transportEntryMap: Record; private _transportExecutorStack: AsyncDisposableStack; constructor(private opts: UnifiedGraphManagerOptions) { this.handleUnifiedGraph = opts.handleUnifiedGraph || handleFederationSupergraph; @@ -185,10 +185,6 @@ export class UnifiedGraphManager { ); } - public getTransportEntryMap() { - return mapMaybePromise(this.ensureUnifiedGraph(), () => this._transportEntryMap); - } - public getUnifiedGraph() { return mapMaybePromise(this.ensureUnifiedGraph(), () => this.unifiedGraph); } diff --git a/packages/fusion/runtime/src/utils.ts b/packages/fusion/runtime/src/utils.ts index ca71965af470c..6719f0eff12eb 100644 --- a/packages/fusion/runtime/src/utils.ts +++ b/packages/fusion/runtime/src/utils.ts @@ -1,4 +1,5 @@ import { print, type DocumentNode, type ExecutionResult, type GraphQLSchema } from 'graphql'; +import type { GraphQLResolveInfo } from 'graphql/type'; import type { TransportEntryAdditions } from '@graphql-mesh/serve-runtime'; import type { Transport, @@ -9,7 +10,12 @@ import type { TransportGetSubgraphExecutorOptions, } from '@graphql-mesh/transport-common'; import type { Logger } from '@graphql-mesh/types'; -import { iterateAsync, mapMaybePromise } from '@graphql-mesh/utils'; +import { + iterateAsync, + loggerForExecutionRequest, + mapMaybePromise, + requestIdByRequest, +} from '@graphql-mesh/utils'; import { isAsyncIterable, isDocumentNode, @@ -167,6 +173,7 @@ export function getOnSubgraphExecute({ onSubgraphExecuteHooks, subgraphName, transportEntryMap, + transportContext, getSubgraphSchema, }); // Caches the executor for future use @@ -188,6 +195,13 @@ export interface WrapExecuteWithHooksOptions { subgraphName: string; transportEntryMap?: Record; getSubgraphSchema: (subgraphName: string) => GraphQLSchema; + transportContext?: TransportContext; +} + +declare module 'graphql' { + interface GraphQLResolveInfo { + executionRequest?: ExecutionRequest; + } } /** @@ -200,11 +214,23 @@ export function wrapExecutorWithHooks({ subgraphName, transportEntryMap, getSubgraphSchema, + transportContext, }: WrapExecuteWithHooksOptions): Executor { - if (onSubgraphExecuteHooks.length === 0) { - return executor; - } return function executorWithHooks(executionRequest: ExecutionRequest) { + executionRequest.info = executionRequest.info || ({} as GraphQLResolveInfo); + executionRequest.info.executionRequest = executionRequest; + const requestId = + executionRequest.context?.request && requestIdByRequest.get(executionRequest.context.request); + let execReqLogger = transportContext?.logger?.child?.(subgraphName); + if (execReqLogger) { + if (requestId) { + execReqLogger = execReqLogger.child(requestId); + } + loggerForExecutionRequest.set(executionRequest, execReqLogger); + } + if (onSubgraphExecuteHooks.length === 0) { + return executor(executionRequest); + } const onSubgraphExecuteDoneHooks: OnSubgraphExecuteDoneHook[] = []; return mapMaybePromise( iterateAsync( @@ -220,12 +246,16 @@ export function wrapExecutorWithHooks({ }, executionRequest, setExecutionRequest(newExecutionRequest) { + execReqLogger.debug('Updating execution request to: ', newExecutionRequest); executionRequest = newExecutionRequest; }, executor, setExecutor(newExecutor) { + execReqLogger.debug('executor has been updated'); executor = newExecutor; }, + requestId, + logger: execReqLogger, }), onSubgraphExecuteDoneHooks, ), @@ -242,6 +272,7 @@ export function wrapExecutorWithHooks({ onSubgraphExecuteDoneHook({ result: currentResult, setResult(newResult: ExecutionResult) { + execReqLogger.debug('overriding result with: ', newResult); currentResult = newResult; }, }), @@ -281,6 +312,8 @@ export function wrapExecutorWithHooks({ onNext({ result: currentResult, setResult: res => { + execReqLogger.debug('overriding result with: ', res); + currentResult = res; }, }), @@ -315,6 +348,8 @@ export interface OnSubgraphExecutePayload { setExecutionRequest(executionRequest: ExecutionRequest): void; executor: Executor; setExecutor(executor: Executor): void; + requestId?: string; + logger?: Logger; } export interface OnSubgraphExecuteDonePayload { diff --git a/packages/legacy/types/src/index.ts b/packages/legacy/types/src/index.ts index 00b092d321fb6..88838f60f0c21 100644 --- a/packages/legacy/types/src/index.ts +++ b/packages/legacy/types/src/index.ts @@ -11,7 +11,7 @@ import type { SubschemaConfig, Transform, } from '@graphql-tools/delegate'; -import type { Executor, IResolvers, MaybePromise } from '@graphql-tools/utils'; +import type { ExecutionRequest, Executor, IResolvers, MaybePromise } from '@graphql-tools/utils'; import type { TypedDocumentNode } from '@graphql-typed-document-node/core'; import * as YamlConfig from './config.js'; @@ -183,6 +183,9 @@ export interface OnFetchHookPayload { info: GraphQLResolveInfo; fetchFn: MeshFetch; setFetchFn: (fetchFn: MeshFetch) => void; + executionRequest?: ExecutionRequest; + logger: Logger; + requestId?: string; } export interface OnFetchHookDonePayload { diff --git a/packages/legacy/utils/src/logger.ts b/packages/legacy/utils/src/logger.ts index 9c0cff24177af..a55ffdc844943 100644 --- a/packages/legacy/utils/src/logger.ts +++ b/packages/legacy/utils/src/logger.ts @@ -33,6 +33,10 @@ export enum LogLevel { const noop: VoidFunction = () => {}; +function getTimestamp() { + return new Date().toISOString(); +} + export class DefaultLogger implements Logger { constructor( public name?: string, @@ -95,7 +99,7 @@ export class DefaultLogger implements Logger { const message = this.getLoggerMessage({ args, }); - const fullMessage = `${this.prefix} ${message}`; + const fullMessage = `[${getTimestamp()}] ${this.prefix} ${message}`; if (process?.stderr?.write(fullMessage + '\n')) { return; } @@ -109,7 +113,7 @@ export class DefaultLogger implements Logger { const message = this.getLoggerMessage({ args, }); - const fullMessage = `${this.prefix} ⚠️ ${warnColor(message)}`; + const fullMessage = `[${getTimestamp()}] ${this.prefix} ⚠️ ${warnColor(message)}`; if (process?.stderr?.write(fullMessage + '\n')) { return; } @@ -123,7 +127,7 @@ export class DefaultLogger implements Logger { const message = this.getLoggerMessage({ args, }); - const fullMessage = `${this.prefix} 💡 ${infoColor(message)}`; + const fullMessage = `[${getTimestamp()}] ${this.prefix} 💡 ${infoColor(message)}`; if (typeof process?.stderr?.write === 'function') { process.stderr.write(fullMessage + '\n'); return; @@ -139,7 +143,7 @@ export class DefaultLogger implements Logger { args, trim: false, }); - const fullMessage = `${this.prefix} 💥 ${errorColor(message)}`; + const fullMessage = `[${getTimestamp()}] ${this.prefix} 💥 ${errorColor(message)}`; if (typeof process?.stderr?.write === 'function') { process.stderr.write(fullMessage + '\n'); return; @@ -155,7 +159,7 @@ export class DefaultLogger implements Logger { const message = this.handleLazyMessage({ lazyArgs, }); - const fullMessage = `${this.prefix} 🐛 ${debugColor(message)}`; + const fullMessage = `[${getTimestamp()}] ${this.prefix} 🐛 ${debugColor(message)}`; if (typeof process?.stderr?.write === 'function') { process.stderr.write(fullMessage + '\n'); return; @@ -165,6 +169,9 @@ export class DefaultLogger implements Logger { } child(name: string): Logger { + if (this.name?.includes(name)) { + return this; + } return new DefaultLogger(this.name ? `${this.name} - ${name}` : name, this.logLevel); } @@ -174,4 +181,8 @@ export class DefaultLogger implements Logger { } return this; } + + toJSON() { + return undefined; + } } diff --git a/packages/legacy/utils/src/wrapFetchWithHooks.ts b/packages/legacy/utils/src/wrapFetchWithHooks.ts index cd3ad031d7a01..7b2dbb8d98db5 100644 --- a/packages/legacy/utils/src/wrapFetchWithHooks.ts +++ b/packages/legacy/utils/src/wrapFetchWithHooks.ts @@ -1,7 +1,12 @@ -import type { MeshFetch, OnFetchHook, OnFetchHookDone } from '@graphql-mesh/types'; +import type { Logger, MeshFetch, OnFetchHook, OnFetchHookDone } from '@graphql-mesh/types'; +import { type ExecutionRequest } from '@graphql-tools/utils'; import { iterateAsync } from './iterateAsync.js'; +import { DefaultLogger } from './logger.js'; import { mapMaybePromise } from './map-maybe-promise.js'; +export const requestIdByRequest = new WeakMap(); +export const loggerForExecutionRequest = new WeakMap(); + export function wrapFetchWithHooks(onFetchHooks: OnFetchHook[]): MeshFetch { return function wrappedFetchFn(url, options, context, info) { let fetchFn: MeshFetch; @@ -25,6 +30,33 @@ export function wrapFetchWithHooks(onFetchHooks: OnFetchHook }, context, info, + get executionRequest() { + return info?.executionRequest; + }, + get requestId() { + if (context?.request) { + return requestIdByRequest.get(context.request); + } + }, + get logger() { + let logger: Logger; + if (info?.executionRequest) { + logger = loggerForExecutionRequest.get(info.executionRequest); + } + if (!logger) { + logger = new DefaultLogger('fetch'); + } + if (context?.request) { + const requestId = requestIdByRequest.get(context.request); + if (requestId) { + logger = logger.child(requestId); + } + } + if (info?.executionRequest) { + loggerForExecutionRequest.set(info.executionRequest, logger); + } + return logger; + }, }), onFetchDoneHooks, ), diff --git a/packages/loaders/openapi/tests/example_api7.test.ts b/packages/loaders/openapi/tests/example_api7.test.ts index a943c9acc9898..d4e49d73eb4d3 100644 --- a/packages/loaders/openapi/tests/example_api7.test.ts +++ b/packages/loaders/openapi/tests/example_api7.test.ts @@ -25,7 +25,7 @@ describe('OpenAPI Loader: example_api7', () => { schema: createdSchema, context: { pubsub }, maskedErrors: false, - logging: false, + logging: !!process.env.DEBUG, }); }); diff --git a/packages/loaders/openapi/tests/file-upload.test.ts b/packages/loaders/openapi/tests/file-upload.test.ts index b8e08496d88db..a57b68d725a7b 100644 --- a/packages/loaders/openapi/tests/file-upload.test.ts +++ b/packages/loaders/openapi/tests/file-upload.test.ts @@ -16,7 +16,7 @@ beforeAll(async () => { createdSchemaYoga = createYoga({ schema: createdSchema, maskedErrors: false, - logging: false, + logging: !!process.env.DEBUG, }); }); diff --git a/packages/plugins/hmac-upstream-signature/src/index.ts b/packages/plugins/hmac-upstream-signature/src/index.ts index e58661f1f9357..0fdac789a52c9 100644 --- a/packages/plugins/hmac-upstream-signature/src/index.ts +++ b/packages/plugins/hmac-upstream-signature/src/index.ts @@ -1,4 +1,4 @@ -import type { FetchAPI, GraphQLParams, Plugin as YogaPlugin } from 'graphql-yoga'; +import type { FetchAPI, GraphQLParams, YogaLogger, Plugin as YogaPlugin } from 'graphql-yoga'; import jsonStableStringify from 'json-stable-stringify'; import type { OnSubgraphExecutePayload } from '@graphql-mesh/fusion-runtime'; import type { MeshServePlugin } from '@graphql-mesh/serve-runtime'; @@ -66,8 +66,11 @@ export function useHmacUpstreamSignature(options: HMACUpstreamSignatureOptions): onYogaInit({ yoga }) { fetchAPI = yoga.fetchAPI; }, - onSubgraphExecute({ subgraphName, subgraph, executionRequest, setExecutionRequest }) { + onSubgraphExecute({ subgraphName, subgraph, executionRequest, setExecutionRequest, logger }) { + logger.debug(`running shouldSign for subgraph ${subgraphName}`); + if (shouldSign({ subgraphName, subgraph, executionRequest })) { + logger.debug(`shouldSign is true for subgraph ${subgraphName}, signing request`); textEncoder ||= new fetchAPI.TextEncoder(); key$ ||= createCryptoKey({ textEncoder, @@ -81,6 +84,10 @@ export function useHmacUpstreamSignature(options: HMACUpstreamSignatureOptions): const encodedContent = textEncoder.encode(serializedExecutionRequest); const signature = await fetchAPI.crypto.subtle.sign('HMAC', key, encodedContent); const extensionValue = btoa(String.fromCharCode(...new Uint8Array(signature))); + logger.debug( + `produced hmac signature for subgraph ${subgraphName}, signature: ${signature}, signed payload: ${serializedExecutionRequest}`, + ); + setExecutionRequest({ ...executionRequest, extensions: { @@ -89,6 +96,8 @@ export function useHmacUpstreamSignature(options: HMACUpstreamSignatureOptions): }, }); }); + } else { + logger.debug(`shouldSign is false for subgraph ${subgraphName}, skipping hmac signature`); } }, }; @@ -110,15 +119,23 @@ export function useHmacSignatureValidation( const extensionName = options.extensionName || DEFAULT_EXTENSION_NAME; let key$: Promise; let textEncoder: TextEncoder; + let logger: YogaLogger; const paramsSerializer = options.serializeParams || defaultParamsSerializer; return { + onYogaInit({ yoga }) { + logger = yoga.logger; + }, onParams({ params, fetchAPI }) { textEncoder ||= new fetchAPI.TextEncoder(); const extension = params.extensions?.[extensionName]; + if (!extension) { + logger.warn(`Missing HMAC signature: extension ${extensionName} not found in request.`); + throw new Error(`Missing HMAC signature: extension ${extensionName} not found in request.`); } + key$ ||= createCryptoKey({ textEncoder, crypto: fetchAPI.crypto, @@ -128,6 +145,10 @@ export function useHmacSignatureValidation( return key$.then(async key => { const sigBuf = Uint8Array.from(atob(extension), c => c.charCodeAt(0)); const serializedParams = paramsSerializer(params); + logger.debug( + `HMAC signature will be calculate based on serialized params: ${serializedParams}`, + ); + const result = await fetchAPI.crypto.subtle.verify( 'HMAC', key, @@ -136,6 +157,8 @@ export function useHmacSignatureValidation( ); if (!result) { + logger.error(`HMAC signature does not match the body content. short circuit request.`); + throw new Error( `Invalid HMAC signature: extension ${extensionName} does not match the body content.`, ); diff --git a/packages/plugins/hmac-upstream-signature/src/useHMACUpstreamSignature.spec.ts b/packages/plugins/hmac-upstream-signature/src/useHMACUpstreamSignature.spec.ts index cef91066e1b0f..1c5f852088e09 100644 --- a/packages/plugins/hmac-upstream-signature/src/useHMACUpstreamSignature.spec.ts +++ b/packages/plugins/hmac-upstream-signature/src/useHMACUpstreamSignature.spec.ts @@ -2,7 +2,7 @@ // eslint-disable-next-line import/no-nodejs-modules import { createHmac } from 'node:crypto'; import { createSchema, createYoga, type Plugin } from 'graphql-yoga'; -import { createServeRuntime } from '@graphql-mesh/serve-runtime'; +import { createServeRuntime, useCustomFetch } from '@graphql-mesh/serve-runtime'; import { defaultParamsSerializer, useHmacSignatureValidation, @@ -102,11 +102,9 @@ describe('useHmacSignatureValidation', () => { proxy: { endpoint: 'https://example.com/graphql', }, - fetchAPI: { - // @ts-expect-error - signature mismatch - fetch: upstream.fetch, - }, plugins: () => [ + // @ts-expect-error - signature mismatch + useCustomFetch(upstream.fetch), { onSubgraphExecute(payload) { payload.executionRequest.extensions ||= {}; @@ -168,11 +166,9 @@ describe('useHmacUpstreamSignature', () => { proxy: { endpoint: 'https://example.com/graphql', }, - fetchAPI: { - // @ts-expect-error - signature mismatch - fetch: upstream.fetch, - }, plugins: () => [ + // @ts-expect-error - signature mismatch + useCustomFetch(upstream.fetch), { onSubgraphExecute(payload) { payload.executionRequest.extensions ||= {}; @@ -219,10 +215,9 @@ describe('useHmacUpstreamSignature', () => { proxy: { endpoint: 'https://example.com/graphql', }, - fetchAPI: { - fetch: upstream.fetch as any, - }, plugins: () => [ + // @ts-expect-error - signature mismatch + useCustomFetch(upstream.fetch), useHmacUpstreamSignature({ secret, }), @@ -264,10 +259,9 @@ describe('useHmacUpstreamSignature', () => { proxy: { endpoint: 'https://example.com/graphql', }, - fetchAPI: { - fetch: upstream.fetch as any, - }, plugins: () => [ + // @ts-expect-error - signature mismatch + useCustomFetch(upstream.fetch), useHmacUpstreamSignature({ secret, extensionName: customExtensionName, @@ -309,10 +303,9 @@ describe('useHmacUpstreamSignature', () => { proxy: { endpoint: 'https://example.com/graphql', }, - fetchAPI: { - fetch: upstream.fetch as any, - }, plugins: () => [ + // @ts-expect-error - signature mismatch + useCustomFetch(upstream.fetch), useHmacUpstreamSignature({ secret, shouldSign: () => { diff --git a/packages/plugins/jwt-auth/src/index.ts b/packages/plugins/jwt-auth/src/index.ts index 76b289ff0b315..9ec1013082b29 100644 --- a/packages/plugins/jwt-auth/src/index.ts +++ b/packages/plugins/jwt-auth/src/index.ts @@ -68,13 +68,18 @@ export function useJWT( // When a subgraph is about to be executed, we check if the initial request has a JWT token // that needs to be passed. At the moment, only GraphQL subgraphs will have the option to forward tokens/payload. // The JWT info will be passed to the subgraph execution request. - onSubgraphExecute({ executionRequest, setExecutionRequest }) { + onSubgraphExecute({ executionRequest, subgraphName, setExecutionRequest, logger }) { if (shouldForward && executionRequest.context.jwt) { const jwtData: Partial = { payload: forwardPayload ? executionRequest.context.jwt.payload : undefined, token: forwardToken ? executionRequest.context.jwt.token : undefined, }; + logger.debug( + `Forwarding JWT payload to subgraph ${subgraphName}, payload: `, + jwtData.payload, + ); + setExecutionRequest({ ...executionRequest, extensions: { diff --git a/packages/plugins/jwt-auth/src/useJWT.spec.ts b/packages/plugins/jwt-auth/src/useJWT.spec.ts index 089f321385883..1d272db2a8243 100644 --- a/packages/plugins/jwt-auth/src/useJWT.spec.ts +++ b/packages/plugins/jwt-auth/src/useJWT.spec.ts @@ -1,6 +1,6 @@ import { createSchema, createYoga, type Plugin } from 'graphql-yoga'; import jwt from 'jsonwebtoken'; -import { createServeRuntime } from '@graphql-mesh/serve-runtime'; +import { createServeRuntime, useCustomFetch } from '@graphql-mesh/serve-runtime'; import { createInlineSigningKeyProvider, type JWTExtendContextFields, @@ -31,10 +31,9 @@ describe('useExtractedJWT', () => { proxy: { endpoint: 'https://example.com/graphql', }, - fetchAPI: { - fetch: upstream.fetch as any, - }, plugins: () => [ + // @ts-expect-error - signature mismatch + useCustomFetch(upstream.fetch), useJWTAuth({ forward: { payload: true, @@ -100,10 +99,9 @@ describe('useJWTAuth', () => { proxy: { endpoint: 'https://example.com/graphql', }, - fetchAPI: { - fetch: upstream.fetch as any, - }, plugins: () => [ + // @ts-expect-error - signature mismatch + useCustomFetch(upstream.fetch), useJWTAuth({ forward: { payload: true, diff --git a/packages/plugins/prometheus/tests/prometheus.spec.ts b/packages/plugins/prometheus/tests/prometheus.spec.ts index ec060ac9ea8fc..d2110dc8f486a 100644 --- a/packages/plugins/prometheus/tests/prometheus.spec.ts +++ b/packages/plugins/prometheus/tests/prometheus.spec.ts @@ -43,7 +43,7 @@ describe('Prometheus', () => { }; }, plugins: ctx => [usePrometheus(ctx)], - logging: false, + logging: !!process.env.DEBUG, }); } diff --git a/packages/serve-runtime/src/createServeRuntime.ts b/packages/serve-runtime/src/createServeRuntime.ts index 205800d01a9e1..414196b1de0dc 100644 --- a/packages/serve-runtime/src/createServeRuntime.ts +++ b/packages/serve-runtime/src/createServeRuntime.ts @@ -52,6 +52,9 @@ import type { import { useChangingSchema } from './useChangingSchema.js'; import { useCompleteSubscriptionsOnDispose } from './useCompleteSubscriptionsOnDispose.js'; import { useCompleteSubscriptionsOnSchemaChange } from './useCompleteSubscriptionsOnSchemaChange.js'; +import { useFetchDebug } from './useFetchDebug.js'; +import { useRequestId } from './useRequestId.js'; +import { useSubgraphExecuteDebug } from './useSubgraphExecuteDebug.js'; export function createServeRuntime = Record>( config: MeshServeConfig = {}, @@ -206,20 +209,24 @@ export function createServeRuntime = Record disposableStack.use(unifiedGraphManager); subgraphInformationHTMLRenderer = async () => { const htmlParts: string[] = []; - let supergraphLoadedPlace: string; + let supergraphLoadedPlace = './supergraph.graphql'; if ('hive' in config && config.hive.endpoint) { supergraphLoadedPlace = 'Hive CDN
' + config.hive.endpoint; } else if ('supergraph' in config) { if (typeof config.supergraph === 'function') { const fnName = config.supergraph.name || ''; supergraphLoadedPlace = `a custom loader ${fnName}`; + } else if (typeof config.supergraph === 'string') { + supergraphLoadedPlace = config.supergraph; } } let loaded = false; let loadError: Error; - let transportEntryMap: Record; try { - transportEntryMap = await unifiedGraphManager.getTransportEntryMap(); + // TODO: Workaround for the issue + // When you go to landing page, then GraphiQL, GW stops working + const schema = await getSchema(); + schemaChanged(schema); loaded = true; } catch (e) { loaded = false; @@ -230,8 +237,8 @@ export function createServeRuntime = Record htmlParts.push(`

Source: ${supergraphLoadedPlace}

`); htmlParts.push(``); htmlParts.push(``); - for (const subgraphName in transportEntryMap) { - const transportEntry = transportEntryMap[subgraphName]; + for (const subgraphName in unifiedGraphManager._transportEntryMap) { + const transportEntry = unifiedGraphManager._transportEntryMap[subgraphName]; htmlParts.push(``); htmlParts.push(``); htmlParts.push(``); @@ -354,6 +361,9 @@ export function createServeRuntime = Record useChangingSchema(getSchema, cb => (schemaChanged = cb)), useCompleteSubscriptionsOnDispose(disposableStack), useCompleteSubscriptionsOnSchemaChange(), + useRequestId(), + useSubgraphExecuteDebug(configContext), + useFetchDebug(configContext), ...(config.plugins?.(configContext) || []), ], // @ts-expect-error PromiseLike is not compatible with Promise diff --git a/packages/serve-runtime/src/useFetchDebug.ts b/packages/serve-runtime/src/useFetchDebug.ts new file mode 100644 index 0000000000000..bdac9431bd2d5 --- /dev/null +++ b/packages/serve-runtime/src/useFetchDebug.ts @@ -0,0 +1,21 @@ +import type { Logger } from '@graphql-mesh/types'; +import type { MeshServePlugin } from './types'; + +export function useFetchDebug(opts: { logger: Logger }): MeshServePlugin { + return { + onFetch({ url, options, logger = opts.logger }) { + logger = logger.child('fetch'); + logger.debug('request', { + url, + ...(options || {}), + }); + return function onFetchDone({ response }) { + logger.debug('response', () => ({ + url, + status: response.status, + headers: Object.fromEntries(response.headers.entries()), + })); + }; + }, + }; +} diff --git a/packages/serve-runtime/src/useRequestId.ts b/packages/serve-runtime/src/useRequestId.ts new file mode 100644 index 0000000000000..41b7a0ea0e17b --- /dev/null +++ b/packages/serve-runtime/src/useRequestId.ts @@ -0,0 +1,29 @@ +import { requestIdByRequest } from '@graphql-mesh/utils'; +import type { MeshServePlugin } from './types'; + +export function useRequestId(): MeshServePlugin { + return { + onRequest({ request, fetchAPI }) { + const requestId = request.headers.get('x-request-id') || fetchAPI.crypto.randomUUID(); + requestIdByRequest.set(request, requestId); + }, + onFetch({ context, options, setOptions }) { + const requestId = requestIdByRequest.get(context?.request); + if (requestId) { + setOptions({ + ...(options || {}), + headers: { + ...(options.headers || {}), + 'x-request-id': requestId, + }, + }); + } + }, + onResponse({ request, response }) { + const requestId = requestIdByRequest.get(request); + if (requestId) { + response.headers.set('x-request-id', requestId); + } + }, + }; +} diff --git a/packages/serve-runtime/src/useSubgraphExecuteDebug.ts b/packages/serve-runtime/src/useSubgraphExecuteDebug.ts new file mode 100644 index 0000000000000..4dbdf54885c07 --- /dev/null +++ b/packages/serve-runtime/src/useSubgraphExecuteDebug.ts @@ -0,0 +1,33 @@ +import { isAsyncIterable } from 'graphql-yoga'; +import { defaultPrintFn } from '@graphql-mesh/transport-common'; +import type { Logger } from '@graphql-mesh/types'; +import type { MeshServePlugin } from './types'; + +export function useSubgraphExecuteDebug(opts: { + logger: Logger; +}): MeshServePlugin { + return { + onSubgraphExecute({ executionRequest, logger = opts.logger }) { + logger.debug(`subgraph-execute`, () => ({ + query: defaultPrintFn(executionRequest.document), + variables: executionRequest.variables, + })); + return function onSubgraphExecuteDone({ result }) { + if (isAsyncIterable(result)) { + return { + onNext(value) { + logger.debug(`subgraph-response-next`, value); + }, + onEnd() { + logger.debug(`subgraph-response-end`); + }, + }; + } + logger.debug(`subgraph-response`, { + data: result.data, + errors: result.errors, + }); + }; + }, + }; +} diff --git a/packages/serve-runtime/tests/serve-runtime.spec.ts b/packages/serve-runtime/tests/serve-runtime.spec.ts index 24755b4aed19f..2d295eb24dc76 100644 --- a/packages/serve-runtime/tests/serve-runtime.spec.ts +++ b/packages/serve-runtime/tests/serve-runtime.spec.ts @@ -10,10 +10,11 @@ import { } from 'graphql'; import { createSchema, createYoga } from 'graphql-yoga'; import { getUnifiedGraphGracefully } from '@graphql-mesh/fusion-composition'; -import type { MeshServePlugin } from '@graphql-mesh/serve-runtime'; import { buildHTTPExecutor } from '@graphql-tools/executor-http'; import { Response } from '@whatwg-node/server'; import { createServeRuntime } from '../src/createServeRuntime.js'; +import type { MeshServePlugin } from '../src/types.js'; +import { useCustomFetch } from '../src/useCustomFetch.js'; describe('Serve Runtime', () => { beforeEach(() => { @@ -21,7 +22,7 @@ describe('Serve Runtime', () => { }); function createSupergraphRuntime() { return createServeRuntime({ - logging: false, + logging: !!process.env.DEBUG, supergraph: () => { if (!upstreamIsUp) { throw new Error('Upstream is down'); @@ -70,12 +71,12 @@ describe('Serve Runtime', () => { } const upstreamAPI = createYoga({ schema: createUpstreamSchema(), - logging: false, + logging: !!process.env.DEBUG, }); let upstreamIsUp = true; const serveRuntimes = { proxyAPI: createServeRuntime({ - logging: false, + logging: !!process.env.DEBUG, proxy: { endpoint: 'http://localhost:4000/graphql', fetch(info, init, ...args) { @@ -191,11 +192,8 @@ describe('Serve Runtime', () => { proxy: { endpoint: 'http://localhost:4000/graphql', }, - fetchAPI: { - fetch: fetchFn, - }, - plugins: () => [mockPlugin], - logging: false, + plugins: () => [useCustomFetch(fetchFn), mockPlugin], + logging: !!process.env.DEBUG, }); const res = await serveRuntime.fetch('http://localhost:4000/graphql', { method: 'POST', @@ -223,7 +221,7 @@ describe('Serve Runtime', () => { it('should invoke onSchemaChange hooks as soon as schema changes', done => { let onSchemaChangeCalls = 0; const serve = createServeRuntime({ - logging: false, + logging: !!process.env.DEBUG, polling: 500, supergraph() { if (onSchemaChangeCalls > 0) { diff --git a/packages/serve-runtime/tests/subscriptions.test.ts b/packages/serve-runtime/tests/subscriptions.test.ts index 99a0ab879ccbe..118c8fae3c230 100644 --- a/packages/serve-runtime/tests/subscriptions.test.ts +++ b/packages/serve-runtime/tests/subscriptions.test.ts @@ -104,7 +104,7 @@ describe('Subscriptions', () => { let changeSchema = false; await using serve = createServeRuntime({ - logging: false, + logging: !!process.env.DEBUG, polling: 500, supergraph() { if (changeSchema) { diff --git a/packages/serve-runtime/tests/useForwardHeaders.spec.ts b/packages/serve-runtime/tests/useForwardHeaders.spec.ts index affc365d23cda..238265dea0253 100644 --- a/packages/serve-runtime/tests/useForwardHeaders.spec.ts +++ b/packages/serve-runtime/tests/useForwardHeaders.spec.ts @@ -1,4 +1,5 @@ import { createSchema, createYoga, type Plugin } from 'graphql-yoga'; +import { useCustomFetch } from '@graphql-mesh/serve-runtime'; import { createServeRuntime } from '../src/createServeRuntime'; import { useForwardHeaders } from '../src/useForwardHeaders'; @@ -20,7 +21,7 @@ describe('useForwardHeaders', () => { }, }), plugins: [requestTrackerPlugin], - logging: false, + logging: !!process.env.DEBUG, }); beforeEach(() => { requestTrackerPlugin.onParams.mockClear(); @@ -30,12 +31,12 @@ describe('useForwardHeaders', () => { proxy: { endpoint: 'http://localhost:4001/graphql', }, - fetchAPI: { + plugins: () => [ // @ts-expect-error: TODO: fix this - fetch: upstream.fetch, - }, - plugins: () => [useForwardHeaders(['x-my-header', 'x-my-other'])], - logging: false, + useCustomFetch(upstream.fetch), + useForwardHeaders(['x-my-header', 'x-my-other']), + ], + logging: !!process.env.DEBUG, }); const response = await serveRuntime.fetch('http://localhost:4000/graphql', { method: 'POST', @@ -76,7 +77,7 @@ describe('useForwardHeaders', () => { }); it("forwards specified headers but doesn't override the provided headers", async () => { await using serveRuntime = createServeRuntime({ - logging: false, + logging: !!process.env.DEBUG, proxy: { endpoint: 'http://localhost:4001/graphql', headers: { @@ -84,11 +85,11 @@ describe('useForwardHeaders', () => { 'x-extra-header': 'extra-value', }, }, - fetchAPI: { + plugins: () => [ // @ts-expect-error: TODO: fix this - fetch: upstream.fetch, - }, - plugins: () => [useForwardHeaders(['x-my-header', 'x-my-other'])], + useCustomFetch(upstream.fetch), + useForwardHeaders(['x-my-header', 'x-my-other']), + ], maskedErrors: false, }); const response = await serveRuntime.fetch('http://localhost:4000/graphql', { diff --git a/website/src/pages/v1/serve/features/custom-plugins.mdx b/website/src/pages/v1/serve/features/custom-plugins.mdx index 3980859cfed97..d7c201b9b1942 100644 --- a/website/src/pages/v1/serve/features/custom-plugins.mdx +++ b/website/src/pages/v1/serve/features/custom-plugins.mdx @@ -148,6 +148,8 @@ This hook is invoked everytime the gateways sends an outgoing HTTP request to an - `executor`: The executor function that will be used to execute the request to the subgraph, and it takes the execution request object. - `setExecutor`: A function to replace the executor function +- `logger`: The logger instance for the specific request that includes the details of the request + and the response. #### `Symbol.asyncDispose` or `Symbol.dispose`
SubgraphTransportLocation
${subgraphName}${transportEntry.kind}