From a066954f4131a143a348e435b95f17f7c11c1378 Mon Sep 17 00:00:00 2001 From: Slava Kim Date: Thu, 2 Jun 2016 18:02:45 -0700 Subject: [PATCH 1/4] Add support for loggerFn Allows graphql to log whenever the executor enters or leaves a subtree; an error occurs; or a resolver starts/ends execution. --- src/__tests__/starWarsQuery-test.js | 56 +++++++++++++++++++ src/execution/execute.js | 86 +++++++++++++++++++++++++---- src/execution/index.js | 1 + src/execution/logging.js | 32 +++++++++++ src/graphql.js | 10 +++- src/index.js | 1 + 6 files changed, 174 insertions(+), 12 deletions(-) create mode 100644 src/execution/logging.js diff --git a/src/__tests__/starWarsQuery-test.js b/src/__tests__/starWarsQuery-test.js index ea3e51c798..766d882a33 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,59 @@ 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 = + tag === TAG.SUBTREE_ERROR || tag === TAG.RESOLVER_ERROR ? + payload.executionPath : 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..32137ad35c 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,32 @@ 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, + executionPath: path, + }, info); + return Promise.reject(reason); + }); + } else { + if (result instanceof Error) { + logFn(TAG.RESOLVER_ERROR, { + error: result, + executionPath: path, + }, info); + } + logFn(TAG.RESOLVER_END, path, info); + } return completeValueCatchingError( exeContext, @@ -619,10 +648,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 +662,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, + executionPath: 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 +696,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, + executionPath: 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, + executionPath: 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'; From e6633a17aed3920ad056011677cca13d0d32c7cd Mon Sep 17 00:00:00 2001 From: Slava Kim Date: Thu, 16 Jun 2016 15:15:06 -0700 Subject: [PATCH 2/4] Normalize the payload to the log function to always have a property `path` --- src/__tests__/starWarsQuery-test.js | 4 +--- src/execution/execute.js | 32 ++++++++++++++--------------- 2 files changed, 17 insertions(+), 19 deletions(-) diff --git a/src/__tests__/starWarsQuery-test.js b/src/__tests__/starWarsQuery-test.js index 766d882a33..b0329f78a0 100644 --- a/src/__tests__/starWarsQuery-test.js +++ b/src/__tests__/starWarsQuery-test.js @@ -574,9 +574,7 @@ describe('Star Wars Query Tests', () => { null, null, (tag, payload) => { - const path = - tag === TAG.SUBTREE_ERROR || tag === TAG.RESOLVER_ERROR ? - payload.executionPath : payload; + const { path } = payload; logged.push([ tag, path ]); }); diff --git a/src/execution/execute.js b/src/execution/execute.js index 32137ad35c..3fe7a9d34d 100644 --- a/src/execution/execute.js +++ b/src/execution/execute.js @@ -584,7 +584,7 @@ function resolveField( }; const logFn = exeContext.logFn || (() => {}); - logFn(TAG.RESOLVER_START, path, info); + logFn(TAG.RESOLVER_START, { path }, info); // Get the resolve function, regardless of if its result is normal // or abrupt (error). @@ -592,11 +592,11 @@ function resolveField( if (isThenable(result)) { result = ((result: any): Promise).then( - passThroughResultAndLog(logFn, TAG.RESOLVER_END, path, info), + passThroughResultAndLog(logFn, TAG.RESOLVER_END, { path }, info), reason => { logFn(TAG.RESOLVER_ERROR, { error: reason, - executionPath: path, + path, }, info); return Promise.reject(reason); }); @@ -604,10 +604,10 @@ function resolveField( if (result instanceof Error) { logFn(TAG.RESOLVER_ERROR, { error: result, - executionPath: path, + path, }, info); } - logFn(TAG.RESOLVER_END, path, info); + logFn(TAG.RESOLVER_END, { path }, info); } return completeValueCatchingError( @@ -649,7 +649,7 @@ function completeValueCatchingError( result: mixed ): mixed { const logFn = exeContext.logFn || (() => {}); - logFn(TAG.SUBTREE_START, path, info); + logFn(TAG.SUBTREE_START, { path }, info); // If the field type is non-nullable, then it is resolved without any // protection from errors. @@ -665,18 +665,18 @@ function completeValueCatchingError( if (isThenable(completed)) { return ((completed: any): Promise).then( - passThroughResultAndLog(logFn, TAG.SUBTREE_END, path, info), + passThroughResultAndLog(logFn, TAG.SUBTREE_END, { path }, info), reason => { logFn(TAG.SUBTREE_ERROR, { error: reason, - executionPath: path + path, }, info); - logFn(TAG.SUBTREE_END, path, info); + logFn(TAG.SUBTREE_END, { path }, info); return Promise.reject(reason); }); } - logFn(TAG.SUBTREE_END, path, info); + logFn(TAG.SUBTREE_END, { path }, info); return completed; } @@ -697,20 +697,20 @@ function completeValueCatchingError( // 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( - passThroughResultAndLog(logFn, TAG.SUBTREE_END, path, info), + passThroughResultAndLog(logFn, TAG.SUBTREE_END, { path }, info), error => { exeContext.errors.push(error); logFn(TAG.SUBTREE_ERROR, { error, - executionPath: path + path }, info); - logFn(TAG.SUBTREE_END, path, info); + logFn(TAG.SUBTREE_END, { path }, info); return Promise.resolve(null); }); } - logFn(TAG.SUBTREE_END, path, info); + logFn(TAG.SUBTREE_END, { path }, info); return completed; } catch (error) { @@ -720,9 +720,9 @@ function completeValueCatchingError( logFn(TAG.SUBTREE_ERROR, { error, - executionPath: path + path }, info); - logFn(TAG.SUBTREE_END, path, info); + logFn(TAG.SUBTREE_END, { path }, info); return null; } From b1eff5808c756f2354f001b88b6b673d09306c4f Mon Sep 17 00:00:00 2001 From: Slava Kim Date: Thu, 16 Jun 2016 16:17:28 -0700 Subject: [PATCH 3/4] add missing log --- src/execution/execute.js | 1 + 1 file changed, 1 insertion(+) diff --git a/src/execution/execute.js b/src/execution/execute.js index 3fe7a9d34d..13ca331de3 100644 --- a/src/execution/execute.js +++ b/src/execution/execute.js @@ -598,6 +598,7 @@ function resolveField( error: reason, path, }, info); + logFn(TAG.RESOLVER_END, { path }); return Promise.reject(reason); }); } else { From 816ab8e7712e8e56160375435831643648da3fa9 Mon Sep 17 00:00:00 2001 From: Slava Kim Date: Wed, 13 Jul 2016 14:32:27 -0700 Subject: [PATCH 4/4] Promise -> Promise<*> --- src/execution/execute.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/execution/execute.js b/src/execution/execute.js index 13ca331de3..50aae13f81 100644 --- a/src/execution/execute.js +++ b/src/execution/execute.js @@ -591,7 +591,7 @@ function resolveField( let result = resolveOrError(resolveFn, source, args, context, info); if (isThenable(result)) { - result = ((result: any): Promise).then( + result = ((result: any): Promise<*>).then( passThroughResultAndLog(logFn, TAG.RESOLVER_END, { path }, info), reason => { logFn(TAG.RESOLVER_ERROR, { @@ -665,7 +665,7 @@ function completeValueCatchingError( ); if (isThenable(completed)) { - return ((completed: any): Promise).then( + return ((completed: any): Promise<*>).then( passThroughResultAndLog(logFn, TAG.SUBTREE_END, { path }, info), reason => { logFn(TAG.SUBTREE_ERROR, {