diff --git a/src/__tests__/starWarsQuery-test.js b/src/__tests__/starWarsQuery-test.js index ea3e51c798..b0329f78a0 100644 --- a/src/__tests__/starWarsQuery-test.js +++ b/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); + }); + }); }); diff --git a/src/execution/execute.js b/src/execution/execute.js index b3f6e538f5..50aae13f81 100644 --- a/src/execution/execute.js +++ b/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; + 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 { 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 = []; 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,10 +649,13 @@ function completeValueCatchingError( path: Array, 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, @@ -630,6 +663,22 @@ function completeValueCatchingError( 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; } } diff --git a/src/execution/index.js b/src/execution/index.js index b1158009ef..3d87a1384c 100644 --- a/src/execution/index.js +++ b/src/execution/index.js @@ -8,3 +8,4 @@ */ export { execute } from './execute'; +export { TAG } from './logging'; diff --git a/src/execution/logging.js b/src/execution/logging.js new file mode 100644 index 0000000000..69d392161e --- /dev/null +++ b/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; // eslint-disable-line + +export function passThroughResultAndLog( + logFn: any, + tag: GraphQLLoggingTagType, + payload: any, + info: any +): any { + return function (result) { + logFn(tag, payload, info); + return result; + }; +} diff --git a/src/graphql.js b/src/graphql.js index 4e4a764c73..4167a0350b 100644 --- a/src/graphql.js +++ b/src/graphql.js @@ -39,6 +39,10 @@ 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, @@ -46,7 +50,8 @@ export function graphql( rootValue?: mixed, contextValue?: mixed, variableValues?: ?{[key: string]: mixed}, - operationName?: ?string + operationName?: ?string, + logFn?: (tag: string, payload: mixed, info: mixed) => void ): Promise { return new Promise(resolve => { const source = new Source(requestString || '', 'GraphQL request'); @@ -62,7 +67,8 @@ export function graphql( rootValue, contextValue, variableValues, - operationName + operationName, + logFn ) ); } diff --git a/src/index.js b/src/index.js index 5a923c244b..8d4fed1c92 100644 --- a/src/index.js +++ b/src/index.js @@ -128,6 +128,7 @@ export { // Execute GraphQL queries. export { execute, + TAG } from './execution';