diff --git a/package.json b/package.json index 309c3573e60..0cfb92e51a3 100644 --- a/package.json +++ b/package.json @@ -33,8 +33,13 @@ "homepage": "https://github.com/apollostack/apollo-proxy#readme", "dependencies": { "babel-polyfill": "^6.5.0", - "express-graphql": "^0.5.1", - "graphql-tools": "^0.3.10" + "graphql-tools": "^0.4.2", + "express-widgetizer": "^0.5.2", + "fs": "0.0.2", + "lodash": "^4.10.0", + "node-uuid": "^1.4.7", + "performance-now": "^0.2.0", + "request": "^2.72.0" }, "devDependencies": { "babel-cli": "^6.6.5", @@ -51,6 +56,7 @@ "eslint-plugin-import": "^1.1.0", "express": "^4.13.4", "express3": "0.0.0", + "graphql": "^0.5.0", "istanbul": "1.0.0-alpha.2", "mocha": "^2.3.3", "multer": "^1.0.3", @@ -59,6 +65,9 @@ "supertest": "^1.0.1", "supertest-as-promised": "^2.0.2" }, + "peerDependencies": { + "graphql": "^0.5.0" + }, "eslintConfig": { "parser": "babel-eslint", "extends": [ diff --git a/src/apolloServer.js b/src/apolloServer.js index 241e30f7757..f3b068b5730 100644 --- a/src/apolloServer.js +++ b/src/apolloServer.js @@ -3,9 +3,11 @@ import { buildSchemaFromTypeDefinitions, addErrorLoggingToSchema, addCatchUndefinedToSchema, + addResolveFunctionsToSchema, + addTracingToResolvers, } from 'graphql-tools'; import { addMockFunctionsToSchema } from 'graphql-tools'; -import graphqlHTTP from 'express-graphql'; +import graphqlHTTP from 'express-widgetizer'; import { GraphQLSchema, formatError } from 'graphql'; // TODO this implementation could use a bit of refactoring. @@ -20,8 +22,14 @@ export default function apolloServer(options, ...rest) { throw new Error(`apolloServer expects exactly one argument, got ${rest.length + 1}`); } // Resolve the Options to get OptionsData. + return (req, res) => { - new Promise(resolve => { + let tracerLogger; + + // TODO instrument ApolloServer's schema creation as well, so you know how long + // it takes. May be a big waste of time to recreate the schema for every request. + + return new Promise(resolve => { resolve(typeof options === 'function' ? options(req) : options); }).then(optionsData => { // Assert that optionsData is in fact an Object. @@ -42,25 +50,40 @@ export default function apolloServer(options, ...rest) { resolvers, // required if mocks is not false and schema is not GraphQLSchema connectors, // required if mocks is not false and schema is not GraphQLSchema logger, + tracer, printErrors, mocks = false, allowUndefinedInResolve = true, pretty, // pass through graphiql = false, // pass through validationRules, // pass through - context = {}, // pass through + context = {}, // pass through, but add tracer if applicable rootValue, // pass through } = optionsData; // would collide with formatError from graphql otherwise const formatErrorFn = optionsData.formatError; + // TODO: currently relies on the fact that start and end both exist + // and appear in the correct order and exactly once. + function processInterval(supertype, subtype, tstamp, intervalMap) { + if (subtype === 'start') { + // eslint-disable-next-line no-param-reassign + intervalMap[supertype] = tstamp; + } + if (subtype === 'end') { + // eslint-disable-next-line no-param-reassign + intervalMap[supertype] = tstamp - intervalMap[supertype]; + } + } + let executableSchema; if (mocks) { // TODO: mocks doesn't yet work with a normal GraphQL schema, but it should! // have to rewrite these functions const myMocks = mocks || {}; executableSchema = buildSchemaFromTypeDefinitions(schema); + addResolveFunctionsToSchema(executableSchema, resolvers || {}); addMockFunctionsToSchema({ schema: executableSchema, mocks: myMocks, @@ -97,6 +120,98 @@ export default function apolloServer(options, ...rest) { } } } + + // Tracer-related stuff ------------------------------------------------ + + tracerLogger = { log: undefined, report: undefined }; + if (tracer) { + tracerLogger = tracer.newLoggerInstance(); + tracerLogger.log('request.info', { + headers: req.headers, + baseUrl: req.baseUrl, + originalUrl: req.originalUrl, + method: req.method, + httpVersion: req.httpVersion, + remoteAddr: req.connection.remoteAddress, + }); + if (context.tracer) { + throw new Error('Property tracer on context already defined, cannot attach Tracer'); + } else { + context.tracer = tracerLogger; + } + if (!executableSchema._apolloTracerApplied) { + addTracingToResolvers(executableSchema); + } + } + + // TODO: move to proper place, make less fragile ... + // calculate timing information from events + function timings(events) { + const resolverDurations = []; + const intervalMap = {}; + + // split by event.type = [ , ] + events.forEach(e => { + const [supertype, subtype] = e.type.split('.'); + switch (supertype) { + case 'request': + case 'parse': + case 'validation': + case 'execution': + case 'parseBody': + case 'parseParams': + processInterval(supertype, subtype, e.timestamp, intervalMap); + break; + case 'resolver': + if (subtype === 'end') { + resolverDurations.push({ + type: 'resolve', + functionName: e.data.functionName, + duration: e.timestamp - events[e.data.startEventId].timestamp, + }); + } + break; + default: + console.error(`Unknown event type ${supertype}`); + } + }); + + const durations = []; + Object.keys(intervalMap).forEach((key) => { + durations.push({ + type: key, + functionName: null, + duration: intervalMap[key], + }); + }); + return durations.concat(resolverDurations); + } + + let extensionsFn = function extensionsFn() { + try { + return { + timings: timings(tracerLogger.report().events), + tracer: tracerLogger.report().events.map(e => ({ + id: e.id, + type: e.type, + ts: e.timestamp, + data: e.data, + })).filter(x => x.type !== 'initialization'), + }; + } catch (e) { + console.error(e); + console.error(e.stack); + } + return {}; + }; + + // XXX ugly way of only passing extensionsFn when tracer is defined. + if (!tracer || req.headers['x-apollo-tracer-extension'] !== 'on') { + extensionsFn = undefined; + } + + // end of Tracer related stuff ------------------------------------------- + // graphQLHTTPOptions return { schema: executableSchema, @@ -106,6 +221,8 @@ export default function apolloServer(options, ...rest) { context, rootValue, graphiql, + logFn: tracerLogger.log, + extensionsFn, }; }).then((graphqlHTTPOptions) => { return graphqlHTTP(graphqlHTTPOptions)(req, res); @@ -119,6 +236,10 @@ export default function apolloServer(options, ...rest) { res .set('Content-Type', 'application/json') .send(JSON.stringify(result)); + return result; + }).then(() => { + // send traces to Apollo Tracer + tracerLogger.submit(); }); }; } diff --git a/test/testApolloServer.js b/test/testApolloServer.js index 9d21b7d7208..70b20d42422 100644 --- a/test/testApolloServer.js +++ b/test/testApolloServer.js @@ -1,5 +1,7 @@ import { apolloServer } from '../src/apolloServer'; +import { MockList } from 'graphql-tools'; import { makeExecutableSchema } from 'graphql-tools'; +import { Tracer } from 'graphql-tools'; import { expect } from 'chai'; import express from 'express'; import request from 'supertest-as-promised'; @@ -49,6 +51,27 @@ const server = apolloServer({ connectors: testConnectors, }); +// XXX this app key is not really a secret. It's here so we can either log it +// or filter it out. +const t1 = new Tracer({ TRACER_APP_KEY: 'BDE05C83-E58F-4837-8D9A-9FB5EA605D2A' }); + +const serverWithTracer = apolloServer({ + schema: testSchema, + resolvers: testResolvers, + connectors: testConnectors, + tracer: t1, +}); + +const jsSchema = makeExecutableSchema({ + typeDefs: testSchema, + resolvers: testResolvers, + connectors: testConnectors, +}); +const vanillaServerWithTracer = apolloServer({ + schema: jsSchema, + tracer: t1, +}); + describe('ApolloServer', () => { it('can serve a basic request', () => { const app = express(); @@ -64,6 +87,89 @@ describe('ApolloServer', () => { return expect(res.body.data).to.deep.equal(expected); }); }); + it('can add tracer', () => { + const app = express(); + app.use('/graphql', serverWithTracer); + const expected = { + stuff: 'stuff', + useTestConnector: 'works', + species: 'ROOTuhu', + }; + return request(app) + .get( + '/graphql?query={stuff useTestConnector species(name: "uhu")}' + ) + .set('X-Apollo-Tracer-Extension', 'on') + .then((res) => { + // TODO: this test is silly. actually test the output + expect(res.body.extensions.timings.length).to.equal(9); + return expect(res.body.data).to.deep.equal(expected); + }); + }); + it('does not return traces unless you ask it to', () => { + const app = express(); + app.use('/graphql', serverWithTracer); + const expected = { + stuff: 'stuff', + useTestConnector: 'works', + species: 'ROOTuhu', + }; + return request(app) + .get( + '/graphql?query={stuff useTestConnector species(name: "uhu")}' + ) + .then((res) => { + // eslint-disable-next-line no-unused-expressions + expect(res.body.extensions).to.be.undefined; + return expect(res.body.data).to.deep.equal(expected); + }); + }); + it('can add tracer to a graphql-js schema', () => { + const app = express(); + app.use('/graphql', vanillaServerWithTracer); + const expected = { + stuff: 'stuff', + useTestConnector: 'works', + species: 'ROOTuhu', + }; + return request(app).get( + '/graphql?query={stuff useTestConnector species(name: "uhu")}' + ) + .set('X-Apollo-Tracer-Extension', 'on') + .then((res) => { + // TODO: this test is silly. actually test the output + expect(res.body.extensions.timings.length).to.equal(9); + return expect(res.body.data).to.deep.equal(expected); + }); + }); + + it('logs tracer events', () => { + const realSendReport = t1.sendReport; + let interceptedReport; + t1.sendReport = (report) => { interceptedReport = report; }; + + const app = express(); + app.use('/graphql', serverWithTracer); + const expected = { + stuff: 'stuff', + useTestConnector: 'works', + species: 'ROOTuhu', + }; + return request(app).get( + '/graphql?query={stuff useTestConnector species(name: "uhu")}' + ) + .set('X-Apollo-Tracer-Extension', 'on') + .then((res) => { + // TODO can have race conditions here if executing tests in parallel? + // probably better to set up separate tracer instance for this. + t1.sendReport = realSendReport; + // TODO: this test is silly. actually test the output + expect(res.body.extensions.timings.length).to.equal(9); + expect(interceptedReport.events.length).to.equal(25); + return expect(res.body.data).to.deep.equal(expected); + }); + }); + it('throws an error if schema is shorthand and resolvers not defined', () => { const app = express(); const verySadServer = apolloServer({ @@ -103,6 +209,54 @@ describe('ApolloServer', () => { return expect(res.body.data).to.deep.equal(expected); }); }); + it('can mock a schema with unions', () => { + const app = express(); + const schema = ` + enum SomeEnum { + X + Y + Z + } + type A { + a: SomeEnum! + } + type B { + b: Int! + } + union C = A | B + type Query { + someCs: [C] + } + schema { + query: Query + } + `; + const mockServer = apolloServer({ + schema, + resolvers: { + C: { + __resolveType(data, ctx, info) { + return info.schema.getType(data.typename); + }, + }, + }, + mocks: { + Int: () => 10, + SomeEnum: () => 'X', + Query: () => ({ + someCs: () => new MockList(40), + }), + }, + }); + app.use('/graphql', mockServer); + return request(app).get( + '/graphql?query={someCs {... on A {a} ... on B {b}}}' + ).then((res) => { + const someCs = res.body.data.someCs; + expect(someCs).to.include({a: 'X'}); + return expect(someCs).to.include({b: 10}); + }); + }); it('can log errors', () => { const app = express(); let lastError;