log server events to logFunction

CHANGELOG.md

@@ -1,5 +1,8 @@
 # Changelog
 
+### v0.2.2
+* Log server events such as request start etc. with logFunction ([@helfer](https://github.com/helfer) in [#78](https://github.com/apollostack/apollo-server/pull/78))
+
 ### v0.2.1
 * Complete refactor of Apollo Server using TypeScript. PR [#41](https://github.com/apollostack/apollo-server/pull/41)
 * Added HAPI integration ([@nnance](https://github.com/nnance) in [#46](https://github.com/apollostack/apollo-server/pull/46))

src/core/runQuery.test.ts

@@ -169,4 +169,37 @@ describe('runQuery', () => {
             return expect(res.data).to.deep.equal(expected);
         });
     });
+
+    it('calls logFunction', () => {
+        const query = `
+        query Q1 {
+            testString
+        }`;
+        const logs = [];
+        const logFn = (...args) => {
+            logs.push(args);
+        };
+        const expected = {
+            testString: 'it works',
+        };
+        return runQuery({
+            schema: Schema,
+            query: query,
+            operationName: 'Q1',
+            variables: { test: 123 },
+            logFunction: logFn,
+        })
+        .then((res) => {
+            expect(res.data).to.deep.equal(expected);
+            expect(logs.length).to.equals(11);
+            expect(logs[0][0]).to.equals('request.start');
+            expect(logs[1][0]).to.equals('request.query');
+            expect(logs[1][1]).to.deep.equals(query);
+            expect(logs[2][0]).to.equals('request.variables');
+            expect(logs[2][1]).to.deep.equals({ test: 123 });
+            expect(logs[3][0]).to.equals('request.operationName');
+            expect(logs[3][1]).to.equals('Q1');
+            expect(logs[10][0]).to.equals('request.end');
+        });
+    });
 });

src/core/runQuery.ts

@@ -3,6 +3,7 @@ import {
     GraphQLResult,
     Document,
     parse,
+    print,
     validate,
     execute,
     formatError,
@@ -34,6 +35,10 @@ export interface QueryOptions {
 function runQuery(options: QueryOptions): Promise<GraphQLResult> {
     let documentAST: Document;
 
+    const logFunction = options.logFunction || function(){ return null; };
+
+    logFunction('request.start');
+
     function format(errors: Array<Error>): Array<Error> {
         // TODO: fix types! shouldn't have to cast.
         // the blocker is that the typings aren't right atm:
@@ -42,12 +47,19 @@ function runQuery(options: QueryOptions): Promise<GraphQLResult> {
         return errors.map(options.formatError || formatError as any) as Array<Error>;
     }
 
+    logFunction('request.query', typeof options.query === 'string' ? options.query : print(options.query));
+    logFunction('request.variables', options.variables);
+    logFunction('request.operationName', options.operationName);
+
     // if query is already an AST, don't parse or validate
     if (typeof options.query === 'string') {
         try {
             // TODO: time this with log function
+            logFunction('parse.start');
             documentAST = parse(options.query as string);
+            logFunction('parse.end');
         } catch (syntaxError) {
+            logFunction('parse.end');
             return Promise.resolve({ errors: format([syntaxError]) });
         }
 
@@ -57,7 +69,9 @@ function runQuery(options: QueryOptions): Promise<GraphQLResult> {
         if (options.validationRules) {
           rules = rules.concat(options.validationRules);
         }
+        logFunction('validation.start');
         const validationErrors = validate(options.schema, documentAST, rules);
+        logFunction('validation.end');
         if (validationErrors.length) {
             return Promise.resolve({ errors: format(validationErrors) });
         }
@@ -66,6 +80,7 @@ function runQuery(options: QueryOptions): Promise<GraphQLResult> {
     }
 
     try {
+        logFunction('execution.start');
         return execute(
             options.schema,
             documentAST,
@@ -74,6 +89,7 @@ function runQuery(options: QueryOptions): Promise<GraphQLResult> {
             options.variables,
             options.operationName
         ).then(gqlResponse => {
+            logFunction('execution.end');
             let response = {
                 data: gqlResponse.data,
             };
@@ -83,9 +99,12 @@ function runQuery(options: QueryOptions): Promise<GraphQLResult> {
             if (options.formatResponse) {
                 response = options.formatResponse(response);
             }
+            logFunction('request.end');
             return response;
         });
     } catch (executionError) {
+        logFunction('execution.end');
+        logFunction('request.end');
         return Promise.resolve({ errors: format([executionError]) });
     }
 }