Ensure network requests are always logged

boonefb · facebook-github-bot · commit 95606c5edfba · 2020-11-16T08:57:50.000-08:00
Reviewed By: jstejada

Differential Revision: D23540723

fbshipit-source-id: a32faa8bfbc70bbd2814225923d014e5cdff83af
diff --git a/packages/relay-experimental/__tests__/useLazyLoadQueryNode-test.js b/packages/relay-experimental/__tests__/useLazyLoadQueryNode-test.js
@@ -611,15 +611,27 @@ describe('useLazyLoadQueryNode', () => {
           name: 'execute.start',
           transactionID: 100000,
         },
+        {
+          name: 'network.start',
+          transactionID: 100001,
+        },
         {
           name: 'queryresource.fetch',
           resourceID: 200000,
           profilerContext: expect.objectContaining({}),
         },
+        {
+          name: 'network.next',
+          transactionID: 100001,
+        },
         {
           name: 'execute.next',
           transactionID: 100000,
         },
+        {
+          name: 'network.complete',
+          transactionID: 100001,
+        },
         {
           name: 'execute.complete',
           transactionID: 100000,
@@ -709,6 +721,11 @@ describe('useLazyLoadQueryNode', () => {
           transactionID: 100000,
           variables: variablesOne,
         },
+        {
+          name: 'network.start',
+          transactionID: 100001,
+          variables: variablesOne,
+        },
         {
           // fetch event for variables one
           name: 'queryresource.fetch',
@@ -724,7 +741,12 @@ describe('useLazyLoadQueryNode', () => {
         {
           // request for variables two starts
           name: 'execute.start',
-          transactionID: 100001,
+          transactionID: 100002,
+          variables: variablesTwo,
+        },
+        {
+          name: 'network.start',
+          transactionID: 100003,
           variables: variablesTwo,
         },
         {
@@ -741,10 +763,18 @@ describe('useLazyLoadQueryNode', () => {
         },
         // fetch event for variables one is skipped
         // since it's already cached and reused
+        {
+          name: 'network.next',
+          transactionID: 100001,
+        },
         {
           name: 'execute.next',
           transactionID: 100000,
         },
+        {
+          name: 'network.complete',
+          transactionID: 100001,
+        },
         {
           name: 'execute.complete',
           transactionID: 100000,
diff --git a/packages/relay-experimental/preloadQuery_DEPRECATED.js b/packages/relay-experimental/preloadQuery_DEPRECATED.js
@@ -188,17 +188,7 @@ function preloadQueryDeduped<TQuery: OperationType>(
     }
   } else if (prevQueryEntry == null || prevQueryEntry.kind !== 'network') {
     // Should fetch but we're not already fetching: fetch!
-    const [logObserver, logRequestInfo] = environment.__createLogObserver(
-      params,
-      variables,
-    );
-    const source = network.execute(
-      params,
-      variables,
-      networkCacheConfig,
-      null,
-      logRequestInfo,
-    );
+    const source = network.execute(params, variables, networkCacheConfig, null);
     const subject = new ReplaySubject();
     nextQueryEntry = {
       cacheKey,
@@ -226,7 +216,6 @@ function preloadQueryDeduped<TQuery: OperationType>(
             }
           }, DEFAULT_PREFETCH_TIMEOUT);
         })
-        .do(logObserver)
         .subscribe({
           complete: () => {
             subject.complete();
diff --git a/packages/relay-runtime/store/RelayModernEnvironment.js b/packages/relay-runtime/store/RelayModernEnvironment.js
@@ -147,7 +147,7 @@ class RelayModernEnvironment implements IEnvironment {
         : 'full';
     this._operationLoader = operationLoader;
     this._operationExecutions = new Map();
-    this._network = config.network;
+    this._network = this.__wrapNetworkWithLogObserver(config.network);
     this._getDataID = config.UNSTABLE_DO_NOT_USE_getDataID ?? defaultGetDataID;
     this._publishQueue = new RelayPublishQueue(
       config.store,
@@ -159,7 +159,8 @@ class RelayModernEnvironment implements IEnvironment {
     this.options = config.options;
     this._isServer = config.isServer ?? false;
 
-    (this: any).__setNet = newNet => (this._network = newNet);
+    (this: any).__setNet = newNet =>
+      (this._network = this.__wrapNetworkWithLogObserver(newNet));
 
     if (__DEV__) {
       const {inspect} = require('./StoreInspector');
@@ -366,20 +367,17 @@ class RelayModernEnvironment implements IEnvironment {
     operation: OperationDescriptor,
     updater?: ?SelectorStoreUpdater,
   |}): RelayObservable<GraphQLResponse> {
-    const [logObserver, logRequestInfo] = this.__createLogObserver(
+    const logObserver = this.__createExecuteLogObserver(
       operation.request.node.params,
       operation.request.variables,
     );
     return RelayObservable.create(sink => {
-      const source = this._network
-        .execute(
-          operation.request.node.params,
-          operation.request.variables,
-          operation.request.cacheConfig || {},
-          null,
-          logRequestInfo,
-        )
-        .do(logObserver);
+      const source = this._network.execute(
+        operation.request.node.params,
+        operation.request.variables,
+        operation.request.cacheConfig || {},
+        null,
+      );
       const executor = RelayModernQueryExecutor.execute({
         operation,
         operationExecutions: this._operationExecutions,
@@ -397,7 +395,7 @@ class RelayModernEnvironment implements IEnvironment {
         treatMissingFieldsAsNull: this._treatMissingFieldsAsNull,
       });
       return () => executor.cancel();
-    });
+    }).do(logObserver);
   }
 
   /**
@@ -423,7 +421,7 @@ class RelayModernEnvironment implements IEnvironment {
     updater?: ?SelectorStoreUpdater,
     uploadables?: ?UploadableMap,
   |}): RelayObservable<GraphQLResponse> {
-    const [logObserver, logRequestInfo] = this.__createLogObserver(
+    const logObserver = this.__createExecuteLogObserver(
       operation.request.node.params,
       operation.request.variables,
     );
@@ -436,18 +434,15 @@ class RelayModernEnvironment implements IEnvironment {
           updater: optimisticUpdater,
         };
       }
-      const source = this._network
-        .execute(
-          operation.request.node.params,
-          operation.request.variables,
-          {
-            ...operation.request.cacheConfig,
-            force: true,
-          },
-          uploadables,
-          logRequestInfo,
-        )
-        .do(logObserver);
+      const source = this._network.execute(
+        operation.request.node.params,
+        operation.request.variables,
+        {
+          ...operation.request.cacheConfig,
+          force: true,
+        },
+        uploadables,
+      );
       const executor = RelayModernQueryExecutor.execute({
         operation,
         operationExecutions: this._operationExecutions,
@@ -465,7 +460,7 @@ class RelayModernEnvironment implements IEnvironment {
         treatMissingFieldsAsNull: this._treatMissingFieldsAsNull,
       });
       return () => executor.cancel();
-    });
+    }).do(logObserver);
   }
 
   /**
@@ -484,6 +479,10 @@ class RelayModernEnvironment implements IEnvironment {
     operation: OperationDescriptor,
     source: RelayObservable<GraphQLResponse>,
   |}): RelayObservable<GraphQLResponse> {
+    const logObserver = this.__createExecuteLogObserver(
+      operation.request.node.params,
+      operation.request.variables,
+    );
     return RelayObservable.create(sink => {
       const executor = RelayModernQueryExecutor.execute({
         operation,
@@ -501,20 +500,20 @@ class RelayModernEnvironment implements IEnvironment {
         treatMissingFieldsAsNull: this._treatMissingFieldsAsNull,
       });
       return () => executor.cancel();
-    });
+    }).do(logObserver);
   }
 
   toJSON(): mixed {
     return `RelayModernEnvironment(${this.configName ?? ''})`;
   }
 
-  __createLogObserver(
+  __createExecuteLogObserver(
     params: RequestParameters,
     variables: Variables,
-  ): [Observer<GraphQLResponse>, LogRequestInfoFunction] {
+  ): Observer<GraphQLResponse> {
     const transactionID = generateID();
     const log = this.__log;
-    const logObserver = {
+    return {
       start: subscription => {
         log({
           name: 'execute.start',
@@ -550,14 +549,72 @@ class RelayModernEnvironment implements IEnvironment {
         });
       },
     };
-    const logRequestInfo = info => {
-      log({
-        name: 'execute.info',
-        transactionID,
-        info,
-      });
+  }
+
+  /**
+   * Wraps the network with logging to ensure that network requests are
+   * always logged. Relying on each network callsite to be wrapped is
+   * untenable and will eventually lead to holes in the logging.
+   */
+  __wrapNetworkWithLogObserver(network: INetwork): INetwork {
+    const that = this;
+    return {
+      execute(
+        params: RequestParameters,
+        variables: Variables,
+        cacheConfig: CacheConfig,
+        uploadables?: ?UploadableMap,
+      ): RelayObservable<GraphQLResponse> {
+        const transactionID = generateID();
+        const log = that.__log;
+        const logObserver = {
+          start: subscription => {
+            log({
+              name: 'network.start',
+              transactionID,
+              params,
+              variables,
+            });
+          },
+          next: response => {
+            log({
+              name: 'network.next',
+              transactionID,
+              response,
+            });
+          },
+          error: error => {
+            log({
+              name: 'network.error',
+              transactionID,
+              error,
+            });
+          },
+          complete: () => {
+            log({
+              name: 'network.complete',
+              transactionID,
+            });
+          },
+          unsubscribe: () => {
+            log({
+              name: 'network.unsubscribe',
+              transactionID,
+            });
+          },
+        };
+        const logRequestInfo = info => {
+          log({
+            name: 'network.info',
+            transactionID,
+            info,
+          });
+        };
+        return network
+          .execute(params, variables, cacheConfig, uploadables, logRequestInfo)
+          .do(logObserver);
+      },
     };
-    return [logObserver, logRequestInfo];
   }
 }
 
diff --git a/packages/relay-runtime/store/RelayStoreTypes.js b/packages/relay-runtime/store/RelayStoreTypes.js
@@ -430,11 +430,6 @@ export type LogEvent =
       // value from ProfilerContext
       +profilerContext: mixed,
     |}
-  | {|
-      +name: 'execute.info',
-      +transactionID: number,
-      +info: mixed,
-    |}
   | {|
       +name: 'execute.start',
       +transactionID: number,
@@ -459,6 +454,35 @@ export type LogEvent =
       +name: 'execute.unsubscribe',
       +transactionID: number,
     |}
+  | {|
+      +name: 'network.info',
+      +transactionID: number,
+      +info: mixed,
+    |}
+  | {|
+      +name: 'network.start',
+      +transactionID: number,
+      +params: RequestParameters,
+      +variables: Variables,
+    |}
+  | {|
+      +name: 'network.next',
+      +transactionID: number,
+      +response: GraphQLResponse,
+    |}
+  | {|
+      +name: 'network.error',
+      +transactionID: number,
+      +error: Error,
+    |}
+  | {|
+      +name: 'network.complete',
+      +transactionID: number,
+    |}
+  | {|
+      +name: 'network.unsubscribe',
+      +transactionID: number,
+    |}
   | {|
       +name: 'store.publish',
       +source: RecordSource,
