diff --git a/packages/apollo-server-core/package.json b/packages/apollo-server-core/package.json index 72981cd30e9..2836a30ef65 100644 --- a/packages/apollo-server-core/package.json +++ b/packages/apollo-server-core/package.json @@ -49,7 +49,7 @@ "apollo-cache-control": "^0.1.1", "apollo-engine-reporting": "0.0.0-beta.8", "apollo-tracing": "^0.2.0-beta.0", - "graphql-extensions": "0.1.0-beta.7", + "graphql-extensions": "0.1.0-beta.12", "graphql-subscriptions": "^0.5.8", "graphql-tools": "^3.0.2", "node-fetch": "^2.1.2", diff --git a/packages/apollo-server-core/src/errors.ts b/packages/apollo-server-core/src/errors.ts index b7e283e8b0f..46801b5c9f2 100644 --- a/packages/apollo-server-core/src/errors.ts +++ b/packages/apollo-server-core/src/errors.ts @@ -245,12 +245,13 @@ export function formatApolloErrors( try { return formatter(error); } catch (err) { - logFunction({ - action: LogAction.cleanup, - step: LogStep.status, - data: err, - key: 'error', - }); + logFunction && + logFunction({ + action: LogAction.cleanup, + step: LogStep.status, + data: err, + key: 'error', + }); if (debug) { return enrichError(err, debug); diff --git a/packages/apollo-server-core/src/logging.ts b/packages/apollo-server-core/src/logging.ts index e30f0b12077..f56724f541e 100644 --- a/packages/apollo-server-core/src/logging.ts +++ b/packages/apollo-server-core/src/logging.ts @@ -1,3 +1,6 @@ +import { GraphQLExtension, GraphQLResponse } from 'graphql-extensions'; +import { print, DocumentNode } from 'graphql'; + export enum LogAction { request, parse, @@ -23,3 +26,81 @@ export interface LogMessage { export interface LogFunction { (message: LogMessage); } + +// A GraphQLExtension that implements the existing logFunction interface. Note +// that now that custom extensions are supported, you may just want to do your +// logging as a GraphQLExtension rather than write a LogFunction. + +export class LogFunctionExtension + implements GraphQLExtension { + private logFunction: LogFunction; + public constructor(logFunction: LogFunction) { + this.logFunction = logFunction; + } + + public requestDidStart(options: { + request: Request; + queryString?: string; + parsedQuery?: DocumentNode; + operationName?: string; + variables?: { [key: string]: any }; + }) { + this.logFunction({ action: LogAction.request, step: LogStep.start }); + const loggedQuery = options.queryString || print(options.parsedQuery); + this.logFunction({ + action: LogAction.request, + step: LogStep.status, + key: 'query', + data: loggedQuery, + }); + this.logFunction({ + action: LogAction.request, + step: LogStep.status, + key: 'variables', + data: options.variables, + }); + this.logFunction({ + action: LogAction.request, + step: LogStep.status, + key: 'operationName', + data: options.operationName, + }); + + return (...errors: Array) => { + // If there are no errors, we log in willSendResponse instead. + if (errors.length) { + this.logFunction({ action: LogAction.request, step: LogStep.end }); + } + }; + } + + public parsingDidStart() { + this.logFunction({ action: LogAction.parse, step: LogStep.start }); + return () => { + this.logFunction({ action: LogAction.parse, step: LogStep.end }); + }; + } + + public validationDidStart() { + this.logFunction({ action: LogAction.validation, step: LogStep.start }); + return () => { + this.logFunction({ action: LogAction.validation, step: LogStep.end }); + }; + } + + public executionDidStart() { + this.logFunction({ action: LogAction.execute, step: LogStep.start }); + return () => { + this.logFunction({ action: LogAction.execute, step: LogStep.end }); + }; + } + + public willSendResponse(o: { graphqlResponse: GraphQLResponse }) { + this.logFunction({ + action: LogAction.request, + step: LogStep.end, + key: 'response', + data: o.graphqlResponse, + }); + } +} diff --git a/packages/apollo-server-core/src/runQuery.test.ts b/packages/apollo-server-core/src/runQuery.test.ts index 393b860bb1e..656e4856c74 100644 --- a/packages/apollo-server-core/src/runQuery.test.ts +++ b/packages/apollo-server-core/src/runQuery.test.ts @@ -56,7 +56,7 @@ const queryType = new GraphQLObjectType({ testContextValue: { type: GraphQLString, resolve(_root, _args, context) { - return context + ' works'; + return context.s + ' works'; }, }, testArgumentValue: { @@ -193,7 +193,7 @@ describe('runQuery', () => { return runQuery({ schema, queryString: query, - context: 'it still', + context: { s: 'it still' }, request: new MockReq(), }).then(res => { expect(res.data).to.deep.equal(expected); @@ -206,9 +206,9 @@ describe('runQuery', () => { return runQuery({ schema, queryString: query, - context: 'it still', + context: { s: 'it still' }, formatResponse: (response, { context }) => { - response['extensions'] = context; + response['extensions'] = context.s; return response; }, request: new MockReq(), diff --git a/packages/apollo-server-core/src/runQuery.ts b/packages/apollo-server-core/src/runQuery.ts index 4b05dd57c2a..3ce9ef265e4 100644 --- a/packages/apollo-server-core/src/runQuery.ts +++ b/packages/apollo-server-core/src/runQuery.ts @@ -4,7 +4,6 @@ import { ExecutionResult, DocumentNode, parse, - print, validate, execute, ExecutionArgs, @@ -29,7 +28,7 @@ import { SyntaxError, } from './errors'; -import { LogStep, LogAction, LogFunction } from './logging'; +import { LogFunction, LogFunctionExtension } from './logging'; export interface GraphQLResponse { data?: object; @@ -86,20 +85,14 @@ function doRunQuery(options: QueryOptions): Promise { throw new Error('Must supply one of queryString and parsedQuery'); } - const logFunction = - options.logFunction || - function() { - return null; - }; const debugDefault = process.env.NODE_ENV !== 'production' && process.env.NODE_ENV !== 'test'; const debug = options.debug !== undefined ? options.debug : debugDefault; - logFunction({ action: LogAction.request, step: LogStep.start }); - const context = options.context || {}; - // If custom extension factories were provided, create per-request extension objects. + // If custom extension factories were provided, create per-request extension + // objects. const extensions = options.extensions ? options.extensions.map(f => f()) : []; // Legacy hard-coded extension factories. The ApolloServer class doesn't use @@ -112,16 +105,23 @@ function doRunQuery(options: QueryOptions): Promise { } else if (options.cacheControl) { extensions.push(new CacheControlExtension(options.cacheControl)); } + if (options.logFunction) { + extensions.push(new LogFunctionExtension(options.logFunction)); + } const extensionStack = new GraphQLExtensionStack(extensions); - // We unconditionally create an extensionStack (so that we don't have to - // litter the rest of this function with `if (extensionStack)`, but we don't - // instrument the schema unless there actually are extensions. + // We unconditionally create an extensionStack, even if there are no + // extensions (so that we don't have to litter the rest of this function with + // `if (extensionStack)`, but we don't instrument the schema unless there + // actually are extensions. We do unconditionally put the stack on the + // context, because if some other call had extensions and the schema is + // already instrumented, that's the only way to get a custom fieldResolver to + // work. if (extensions.length > 0) { - context._extensionStack = extensionStack; enableGraphQLExtensions(options.schema); } + context._extensionStack = extensionStack; const requestDidEnd = extensionStack.requestDidStart({ // Since the Request interfacess are not the same between node-fetch and @@ -129,29 +129,13 @@ function doRunQuery(options: QueryOptions): Promise { // into requestDidStart to only the ones we need, currently just the // headers, method, and url request: options.request as any, + queryString: options.queryString, + parsedQuery: options.parsedQuery, + operationName: options.operationName, + variables: options.variables, }); return Promise.resolve() .then(() => { - const loggedQuery = options.queryString || print(options.parsedQuery); - logFunction({ - action: LogAction.request, - step: LogStep.status, - key: 'query', - data: loggedQuery, - }); - logFunction({ - action: LogAction.request, - step: LogStep.status, - key: 'variables', - data: options.variables, - }); - logFunction({ - action: LogAction.request, - step: LogStep.status, - key: 'operationName', - data: options.operationName, - }); - // Parse the document. let documentAST: DocumentNode; if (options.parsedQuery) { @@ -159,7 +143,6 @@ function doRunQuery(options: QueryOptions): Promise { } else if (!options.queryString) { throw new Error('Must supply one of queryString and parsedQuery'); } else { - logFunction({ action: LogAction.parse, step: LogStep.start }); const parsingDidEnd = extensionStack.parsingDidStart({ queryString: options.queryString, }); @@ -180,7 +163,6 @@ function doRunQuery(options: QueryOptions): Promise { ); } finally { parsingDidEnd(...(graphqlParseErrors || [])); - logFunction({ action: LogAction.parse, step: LogStep.end }); if (graphqlParseErrors) { return Promise.resolve({ errors: graphqlParseErrors }); } @@ -200,7 +182,6 @@ function doRunQuery(options: QueryOptions): Promise { if (options.validationRules) { rules = rules.concat(options.validationRules); } - logFunction({ action: LogAction.validation, step: LogStep.start }); const validationDidEnd = extensionStack.validationDidStart(); let validationErrors; try { @@ -217,14 +198,13 @@ function doRunQuery(options: QueryOptions): Promise { ), { formatter: options.formatError, - logFunction, + logFunction: options.logFunction, debug, }, ); } } finally { validationDidEnd(...(validationErrors || [])); - logFunction({ action: LogAction.validation, step: LogStep.end }); if (validationErrors && validationErrors.length) { return Promise.resolve({ @@ -243,7 +223,6 @@ function doRunQuery(options: QueryOptions): Promise { operationName: options.operationName, fieldResolver: options.fieldResolver, }; - logFunction({ action: LogAction.execute, step: LogStep.start }); const executionDidEnd = extensionStack.executionDidStart({ executionArgs, }); @@ -271,13 +250,12 @@ function doRunQuery(options: QueryOptions): Promise { if (result.errors) { response.errors = formatApolloErrors([...result.errors], { formatter: options.formatError, - logFunction, + logFunction: options.logFunction, debug, }); } executionDidEnd(...result.errors); - logFunction({ action: LogAction.execute, step: LogStep.end }); const formattedExtensions = extensionStack.format(); if (Object.keys(formattedExtensions).length > 0) { @@ -296,18 +274,11 @@ function doRunQuery(options: QueryOptions): Promise { // we're not returning a GraphQL response so we don't call // willSendResponse. requestDidEnd(err); - logFunction({ action: LogAction.request, step: LogStep.end }); throw err; }) .then(graphqlResponse => { extensionStack.willSendResponse({ graphqlResponse }); requestDidEnd(); - logFunction({ - action: LogAction.request, - step: LogStep.end, - key: 'response', - data: graphqlResponse, - }); return graphqlResponse; }); }