Logging support

src/__tests__/starWarsQuery-test.js

@@ -11,6 +11,7 @@ import { expect } from 'chai';
 import { describe, it } from 'mocha';
 import { StarWarsSchema } from './starWarsSchema.js';
 import { graphql } from '../graphql';
+import { TAG } from '../execution';
 import {
   GraphQLObjectType,
   GraphQLNonNull,
@@ -528,4 +529,57 @@ describe('Star Wars Query Tests', () => {
           [ [ 'nullableA', 'nullableA', 'nonNullA', 'nonNullA', 'throws' ] ]);
     });
   });
+
+  describe('Allows to pass in a logger function', () => {
+    it('Logs on errors', async () => {
+      const query = `
+        query HeroNameQuery {
+          mainHero: hero {
+            name
+            story: secretBackstory
+          }
+        }
+      `;
+
+      const expected = {
+        mainHero: {
+          name: 'R2-D2',
+          story: null,
+        }
+      };
+
+      const logged = [];
+      const expectedLogged = [
+        [ TAG.RESOLVER_START, [ 'mainHero' ] ],
+        [ TAG.RESOLVER_END, [ 'mainHero' ] ],
+        [ TAG.SUBTREE_START, [ 'mainHero' ] ],
+        [ TAG.RESOLVER_START, [ 'mainHero', 'name' ] ],
+        [ TAG.RESOLVER_END, [ 'mainHero', 'name' ] ],
+        [ TAG.SUBTREE_START, [ 'mainHero', 'name' ] ],
+        [ TAG.SUBTREE_END, [ 'mainHero', 'name' ] ],
+        [ TAG.RESOLVER_START, [ 'mainHero', 'story' ] ],
+        [ TAG.RESOLVER_ERROR, [ 'mainHero', 'story' ] ],
+        [ TAG.RESOLVER_END, [ 'mainHero', 'story' ] ],
+        [ TAG.SUBTREE_START, [ 'mainHero', 'story' ] ],
+        [ TAG.SUBTREE_ERROR, [ 'mainHero', 'story' ] ],
+        [ TAG.SUBTREE_END, [ 'mainHero', 'story' ] ],
+        [ TAG.SUBTREE_END, [ 'mainHero' ] ],
+      ];
+
+      const result = await graphql(
+        StarWarsSchema,
+        query,
+        null,
+        null,
+        null,
+        null,
+        (tag, payload) => {
+          const { path } = payload;
+          logged.push([ tag, path ]);
+        });
+
+      expect(result.data).to.deep.equal(expected);
+      expect(logged).to.deep.equal(expectedLogged);
+    });
+  });
 });

src/execution/execute.js

@@ -15,6 +15,7 @@ import isNullish from '../jsutils/isNullish';
 import { typeFromAST } from '../utilities/typeFromAST';
 import { Kind } from '../language';
 import { getVariableValues, getArgumentValues } from './values';
+import { TAG, passThroughResultAndLog } from './logging';
 import {
   GraphQLScalarType,
   GraphQLObjectType,
@@ -88,6 +89,7 @@ type ExecutionContext = {
   operation: OperationDefinition;
   variableValues: {[key: string]: mixed};
   errors: Array<GraphQLError>;
+  logFn?: (tag: string, payload: mixed, info: mixed) => void
 }
 
 /**
@@ -114,7 +116,8 @@ export function execute(
   rootValue?: mixed,
   contextValue?: mixed,
   variableValues?: ?{[key: string]: mixed},
-  operationName?: ?string
+  operationName?: ?string,
+  logFn?: (tag: string, payload: mixed, info: mixed) => void
 ): Promise<ExecutionResult> {
   invariant(schema, 'Must provide schema');
   invariant(
@@ -131,7 +134,8 @@ export function execute(
     rootValue,
     contextValue,
     variableValues,
-    operationName
+    operationName,
+    logFn
   );
 
   // Return a Promise that will eventually resolve to the data described by
@@ -169,7 +173,8 @@ function buildExecutionContext(
   rootValue: mixed,
   contextValue: mixed,
   rawVariableValues: ?{[key: string]: mixed},
-  operationName: ?string
+  operationName: ?string,
+  logFn?: (tag: string, payload: mixed, info: mixed) => void
 ): ExecutionContext {
   const errors: Array<GraphQLError> = [];
   let operation: ?OperationDefinition;
@@ -216,7 +221,8 @@ function buildExecutionContext(
     contextValue,
     operation,
     variableValues,
-    errors
+    errors,
+    logFn,
   };
 }
 
@@ -577,9 +583,33 @@ function resolveField(
     variableValues: exeContext.variableValues,
   };
 
+  const logFn = exeContext.logFn || (() => {});
+  logFn(TAG.RESOLVER_START, { path }, info);
+
   // Get the resolve function, regardless of if its result is normal
   // or abrupt (error).
-  const result = resolveOrError(resolveFn, source, args, context, info);
+  let result = resolveOrError(resolveFn, source, args, context, info);
+
+  if (isThenable(result)) {
+    result = ((result: any): Promise<*>).then(
+      passThroughResultAndLog(logFn, TAG.RESOLVER_END, { path }, info),
+      reason => {
+        logFn(TAG.RESOLVER_ERROR, {
+          error: reason,
+          path,
+        }, info);
+        logFn(TAG.RESOLVER_END, { path });
+        return Promise.reject(reason);
+      });
+  } else {
+    if (result instanceof Error) {
+      logFn(TAG.RESOLVER_ERROR, {
+        error: result,
+        path,
+      }, info);
+    }
+    logFn(TAG.RESOLVER_END, { path }, info);
+  }
 
   return completeValueCatchingError(
     exeContext,
@@ -619,17 +649,36 @@ function completeValueCatchingError(
   path: Array<string | number>,
   result: mixed
 ): mixed {
+  const logFn = exeContext.logFn || (() => {});
+  logFn(TAG.SUBTREE_START, { path }, info);
+
   // If the field type is non-nullable, then it is resolved without any
   // protection from errors.
   if (returnType instanceof GraphQLNonNull) {
-    return completeValue(
+    const completed = completeValue(
       exeContext,
       returnType,
       fieldASTs,
       info,
       path,
       result
     );
+
+    if (isThenable(completed)) {
+      return ((completed: any): Promise<*>).then(
+        passThroughResultAndLog(logFn, TAG.SUBTREE_END, { path }, info),
+        reason => {
+          logFn(TAG.SUBTREE_ERROR, {
+            error: reason,
+            path,
+          }, info);
+          logFn(TAG.SUBTREE_END, { path }, info);
+          return Promise.reject(reason);
+        });
+    }
+
+    logFn(TAG.SUBTREE_END, { path }, info);
+    return completed;
   }
 
   // Otherwise, error protection is applied, logging the error and resolving
@@ -648,16 +697,34 @@ function completeValueCatchingError(
       // error and resolve to null.
       // Note: we don't rely on a `catch` method, but we do expect "thenable"
       // to take a second callback for the error case.
-      return ((completed: any): Promise<*>).then(undefined, error => {
-        exeContext.errors.push(error);
-        return Promise.resolve(null);
-      });
+      return ((completed: any): Promise<*>).then(
+        passThroughResultAndLog(logFn, TAG.SUBTREE_END, { path }, info),
+        error => {
+          exeContext.errors.push(error);
+          logFn(TAG.SUBTREE_ERROR, {
+            error,
+            path
+          }, info);
+          logFn(TAG.SUBTREE_END, { path }, info);
+
+          return Promise.resolve(null);
+        });
     }
+
+    logFn(TAG.SUBTREE_END, { path }, info);
+
     return completed;
   } catch (error) {
     // If `completeValue` returned abruptly (threw an error), log the error
     // and return null.
     exeContext.errors.push(error);
+
+    logFn(TAG.SUBTREE_ERROR, {
+      error,
+      path
+    }, info);
+    logFn(TAG.SUBTREE_END, { path }, info);
+
     return null;
   }
 }

src/execution/index.js

@@ -8,3 +8,4 @@
  */
 
 export { execute } from './execute';
+export { TAG } from './logging';

src/execution/logging.js

@@ -0,0 +1,32 @@
+/* @flow */
+/**
+ *  Copyright (c) 2015, Facebook, Inc.
+ *  All rights reserved.
+ *
+ *  This source code is licensed under the BSD-style license found in the
+ *  LICENSE file in the root directory of this source tree. An additional grant
+ *  of patent rights can be found in the PATENTS file in the same directory.
+ */
+
+export const TAG = {
+  SUBTREE_START: 'SUBTREE_START',
+  SUBTREE_END: 'SUBTREE_END',
+  SUBTREE_ERROR: 'SUBTREE_ERROR',
+  RESOLVER_START: 'RESOLVER_START',
+  RESOLVER_END: 'RESOLVER_END',
+  RESOLVER_ERROR: 'RESOLVER_ERROR',
+};
+
+export type GraphQLLoggingTagType = $Keys<typeof TAG>; // eslint-disable-line
+
+export function passThroughResultAndLog(
+  logFn: any,
+  tag: GraphQLLoggingTagType,
+  payload: any,
+  info: any
+): any {
+  return function (result) {
+    logFn(tag, payload, info);
+    return result;
+  };
+}

src/graphql.js

@@ -39,14 +39,19 @@ import type { GraphQLSchema } from './type/schema';
  *    The name of the operation to use if requestString contains multiple
  *    possible operations. Can be omitted if requestString contains only
  *    one operation.
+ * logFn:
+ *    The function that is called with a tag of an event, an event payload
+ *    and other execution information.
+ *    The examples include: errors thrown, before and after the resolver call.
  */
 export function graphql(
   schema: GraphQLSchema,
   requestString: string,
   rootValue?: mixed,
   contextValue?: mixed,
   variableValues?: ?{[key: string]: mixed},
-  operationName?: ?string
+  operationName?: ?string,
+  logFn?: (tag: string, payload: mixed, info: mixed) => void
 ): Promise<GraphQLResult> {
   return new Promise(resolve => {
     const source = new Source(requestString || '', 'GraphQL request');
@@ -62,7 +67,8 @@ export function graphql(
           rootValue,
           contextValue,
           variableValues,
-          operationName
+          operationName,
+          logFn
         )
       );
     }

src/index.js

@@ -128,6 +128,7 @@ export {
 // Execute GraphQL queries.
 export {
   execute,
+  TAG
 } from './execution';