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] <github-actions[bot]@users.noreply.github.com> Co-authored-by: Dotan Simha <[email protected]>
ardatan · Jul 25, 2024 · 597e790 · 597e790
1 parent e3945ca
commit 597e790
Show file tree

Hide file tree

Showing 25 changed files with 301 additions and 74 deletions.
diff --git a/.changeset/chilled-bees-lick.md 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -77,7 +77,7 @@ export class UnifiedGraphManager<TContext> {
   private inContextSDK;
   private initialUnifiedGraph$: MaybePromise<true>;
   private disposableStack = new AsyncDisposableStack();
-  private _transportEntryMap: Record<string, TransportEntry>;
+  _transportEntryMap: Record<string, TransportEntry>;
   private _transportExecutorStack: AsyncDisposableStack;
   constructor(private opts: UnifiedGraphManagerOptions<TContext>) {
     this.handleUnifiedGraph = opts.handleUnifiedGraph || handleFederationSupergraph;
@@ -185,10 +185,6 @@ export class UnifiedGraphManager<TContext> {
     );
   }
 
-  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
@@ -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<string, TransportEntry>;
   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<TContext> {
   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
@@ -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<TContext> {
   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
@@ -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
@@ -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<Request, string>();
+export const loggerForExecutionRequest = new WeakMap<ExecutionRequest, Logger>();
+
 export function wrapFetchWithHooks<TContext>(onFetchHooks: OnFetchHook<TContext>[]): MeshFetch {
   return function wrappedFetchFn(url, options, context, info) {
     let fetchFn: MeshFetch;
@@ -25,6 +30,33 @@ export function wrapFetchWithHooks<TContext>(onFetchHooks: OnFetchHook<TContext>
             },
             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
@@ -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
@@ -16,7 +16,7 @@ beforeAll(async () => {
   createdSchemaYoga = createYoga({
     schema: createdSchema,
     maskedErrors: false,
-    logging: false,
+    logging: !!process.env.DEBUG,
   });
 });