refactor: Introduce "tracing" plugin and switch request pipeline to u…

…se it.

This commit introduces a `plugin` (named) export from the `apollo-tracing`
package, which uses the new "plugin" hooks rather than the previous
implementation (exported as `TracingExtension`) which uses the
soon-to-be-deprecated "extensions" hooks.  The functionality is intended to
be identical, in spirit.

Since the delta of the commits was otherwise confusing, I've left the
`TracingExtension` present and exported and will remove it in a subsequent
commit.

Briefly summarizing what the necessary changes were:

1. We no longer use a class instance to house the extension, which was
   necessitated by the `graphql-extensions` API.  This means that uses of
   `this` have been replaced with function scoped variables by the same name.
2. The logic which actually does the formatting (previously handled by the
   `format` method in `graphql-extension`, now takes place within the plugin
   API's `willSendResponse` method.

packages/apollo-server-core/src/ApolloServer.ts

@@ -70,6 +70,7 @@ import {
 import { Headers } from 'apollo-server-env';
 import { buildServiceDefinition } from '@apollographql/apollo-tools';
 import { Logger } from "apollo-server-types";
+import { plugin as pluginTracing } from "apollo-tracing";
 
 const NoIntrospection = (context: ValidationContext) => ({
   Field(node: FieldDefinitionNode) {
@@ -783,11 +784,13 @@ export class ApolloServerBase {
   }
 
   private ensurePluginInstantiation(plugins?: PluginDefinition[]): void {
-    if (!plugins || !plugins.length) {
-      return;
+    const pluginsToInit = [...plugins || []];
+
+    if (this.config.tracing) {
+      pluginsToInit.push(pluginTracing())
     }
 
-    this.plugins = plugins.map(plugin => {
+    this.plugins = pluginsToInit.map(plugin => {
       if (typeof plugin === 'function') {
         return plugin();
       }

packages/apollo-server-core/src/requestPipeline.ts

@@ -26,7 +26,6 @@ import {
   CacheControlExtension,
   CacheControlExtensionOptions,
 } from 'apollo-cache-control';
-import { TracingExtension } from 'apollo-tracing';
 import {
   ApolloError,
   fromGraphQLError,
@@ -95,7 +94,6 @@ export interface GraphQLRequestPipelineConfig<TContext> {
   dataSources?: () => DataSources<TContext>;
 
   extensions?: Array<() => GraphQLExtension>;
-  tracing?: boolean;
   persistedQueries?: PersistedQueryOptions;
   cacheControl?: CacheControlExtensionOptions;
 
@@ -600,10 +598,6 @@ export async function processGraphQLRequest<TContext>(
     // objects.
     const extensions = config.extensions ? config.extensions.map(f => f()) : [];
 
-    if (config.tracing) {
-      extensions.push(new TracingExtension());
-    }
-
     if (config.cacheControl) {
       cacheControlExtension = new CacheControlExtension(config.cacheControl);
       extensions.push(cacheControlExtension);

packages/apollo-tracing/package.json

@@ -12,6 +12,7 @@
   },
   "dependencies": {
     "apollo-server-env": "file:../apollo-server-env",
+    "apollo-server-plugin-base": "file:../apollo-server-plugin-base",
     "graphql-extensions": "file:../graphql-extensions"
   },
   "peerDependencies": {

packages/apollo-tracing/src/index.ts

@@ -4,7 +4,7 @@ import {
   GraphQLResolveInfo,
   GraphQLType,
 } from 'graphql';
-
+import { ApolloServerPlugin } from "apollo-server-plugin-base";
 import { GraphQLExtension } from 'graphql-extensions';
 
 export interface TracingFormat {
@@ -33,6 +33,97 @@ interface ResolverCall {
   endOffset?: HighResolutionTime;
 }
 
+export const plugin = (_futureOptions = {}) => (): ApolloServerPlugin => ({
+  requestDidStart() {
+    let startWallTime: Date | undefined;
+    let endWallTime: Date | undefined;
+    let startHrTime: HighResolutionTime | undefined;
+    let duration: HighResolutionTime | undefined;
+    const resolverCalls: ResolverCall[] = [];
+
+    startWallTime = new Date();
+    startHrTime = process.hrtime();
+
+    return {
+      executionDidStart() {
+        // It's a little odd that we record the end time after execution rather
+        // than at the end of the whole request, but because we need to include
+        // our formatted trace in the request itself, we have to record it
+        // before the request is over! It's also odd that we don't do traces for
+        // parse or validation errors, but runQuery doesn't currently support
+        // that, as format() is only invoked after execution.
+        return () => {
+          duration = process.hrtime(startHrTime);
+          endWallTime = new Date();
+        };
+      },
+      willResolveField(...args) {
+        const [, , , info] = args;
+
+        const resolverCall: ResolverCall = {
+          path: info.path,
+          fieldName: info.fieldName,
+          parentType: info.parentType,
+          returnType: info.returnType,
+          startOffset: process.hrtime(startHrTime),
+        };
+
+        resolverCalls.push(resolverCall);
+
+        return () => {
+          resolverCall.endOffset = process.hrtime(startHrTime);
+        };
+      },
+      willSendResponse({ response }) {
+        // In the event that we are called prior to the initialization of
+        // critical date metrics, we'll return undefined to signal that the
+        // extension did not format properly. Any undefined extension
+        // results are simply purged by the graphql-extensions module.
+        if (
+          typeof startWallTime === 'undefined' ||
+          typeof endWallTime === 'undefined' ||
+          typeof duration === 'undefined'
+        ) {
+          return;
+        }
+
+        const extensions =
+          response.extensions || (response.extensions = Object.create(null));
+
+        if (typeof extensions.tracing !== 'undefined') {
+          throw new Error("The tracing information already existed.");
+        }
+
+        // Set the extensions.
+        extensions.tracing = {
+          version: 1,
+          startTime: startWallTime.toISOString(),
+          endTime: endWallTime.toISOString(),
+          duration: durationHrTimeToNanos(duration),
+          execution: {
+            resolvers: resolverCalls.map(resolverCall => {
+              const startOffset = durationHrTimeToNanos(
+                resolverCall.startOffset,
+              );
+              const duration = resolverCall.endOffset
+                ? durationHrTimeToNanos(resolverCall.endOffset) - startOffset
+                : 0;
+              return {
+                path: [...responsePathAsArray(resolverCall.path)],
+                parentType: resolverCall.parentType.toString(),
+                fieldName: resolverCall.fieldName,
+                returnType: resolverCall.returnType.toString(),
+                startOffset,
+                duration,
+              };
+            }),
+          },
+        };
+      },
+    };
+  },
+})
+
 export class TracingExtension<TContext = any>
   implements GraphQLExtension<TContext> {
   private startWallTime?: Date;

packages/apollo-tracing/tsconfig.json

@@ -8,5 +8,6 @@
   "exclude": ["**/__tests__", "**/__mocks__"],
   "references": [
     { "path": "../graphql-extensions" },
+    { "path": "../apollo-server-plugin-base" },
   ]
 }