apollo-engine-reporting: fix reporting errors from backends

The extension stack executionDidEnd method gets called before didEncounterErrors
for GraphQL errors returned from execution (although confusingly the plugin
executionDidEnd method gets called after), which caused the assertion that
nothing gets added to the EngineReportingTreeBuilder after stopTiming to
fail. Fix by moving stopTiming to the last possible moment: format().

Actually test error reporting, including both kinds of rewriting.

Add a comment noting that backend parse and validation errors don't get
reported.

Fixes #3052.

packages/apollo-engine-reporting/src/federatedExtension.ts

@@ -1,5 +1,5 @@
 import { GraphQLResolveInfo, GraphQLError } from 'graphql';
-import { GraphQLExtension, EndHandler } from 'graphql-extensions';
+import { GraphQLExtension } from 'graphql-extensions';
 import { Trace } from 'apollo-engine-reporting-protobuf';
 import { GraphQLRequestContext } from 'apollo-server-types';
 
@@ -53,30 +53,27 @@ export class EngineFederatedTracingExtension<TContext = any>
     }
   }
 
-  public executionDidStart(): EndHandler | void {
-    if (this.enabled) {
-      // 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 () => {
-        this.treeBuilder.stopTiming();
-        this.done = true;
-      };
-    }
-  }
-
   // The ftv1 extension is a base64'd Trace protobuf containing only the
   // durationNs, startTime, endTime, and root fields.
+  //
+  // Note: format() is only called after executing an operation, and
+  // specifically isn't called for parse or validation errors. Parse and validation
+  // errors in a federated backend will get reported to the end user as a downstream
+  // error but will not get reported to Engine (because Engine filters out downstream
+  // errors)!
   public format(): [string, string] | undefined {
     if (!this.enabled) {
       return;
     }
-    if (!this.done) {
-      throw Error('format called before end of execution?');
+    if (this.done) {
+      throw Error('format called twice?');
     }
+
+    // We record the end time at the latest possible time: right before serializing the trace.
+    // If we wait any longer, the time we record won't actually be sent anywhere!
+    this.treeBuilder.stopTiming();
+    this.done = true;
+
     const encodedUint8Array = Trace.encode(this.treeBuilder.trace).finish();
     const encodedBuffer = Buffer.from(
       encodedUint8Array,

packages/apollo-engine-reporting/src/treeBuilder.ts

@@ -6,6 +6,10 @@ import {
 } from 'graphql';
 import { Trace, google } from 'apollo-engine-reporting-protobuf';
 
+function internalError(message: string) {
+  return new Error(`[internal apollo-server error] ${message}`);
+}
+
 export class EngineReportingTreeBuilder {
   private rootNode = new Trace.Node();
   public trace = new Trace({ root: this.rootNode });
@@ -24,21 +28,21 @@ export class EngineReportingTreeBuilder {
 
   public startTiming() {
     if (this.startHrTime) {
-      throw Error('startTiming called twice!');
+      throw internalError('startTiming called twice!');
     }
     if (this.stopped) {
-      throw Error('startTiming called after stopTiming!');
+      throw internalError('startTiming called after stopTiming!');
     }
     this.trace.startTime = dateToProtoTimestamp(new Date());
     this.startHrTime = process.hrtime();
   }
 
   public stopTiming() {
     if (!this.startHrTime) {
-      throw Error('stopTiming called before startTiming!');
+      throw internalError('stopTiming called before startTiming!');
     }
     if (this.stopped) {
-      throw Error('stopTiming called twice!');
+      throw internalError('stopTiming called twice!');
     }
 
     this.trace.durationNs = durationHrTimeToNanos(
@@ -50,10 +54,10 @@ export class EngineReportingTreeBuilder {
 
   public willResolveField(info: GraphQLResolveInfo): () => void {
     if (!this.startHrTime) {
-      throw Error('willResolveField called before startTiming!');
+      throw internalError('willResolveField called before startTiming!');
     }
     if (this.stopped) {
-      throw Error('willResolveField called after stopTiming!');
+      throw internalError('willResolveField called after stopTiming!');
     }
 
     const path = info.path;
@@ -75,6 +79,10 @@ export class EngineReportingTreeBuilder {
     errors.forEach(err => {
       // This is an error from a federated service. We will already be reporting
       // it in the nested Trace in the query plan.
+      //
+      // XXX This probably shouldn't skip query or validation errors, which are
+      //      not in nested Traces because format() isn't called in this case! Or
+      //      maybe format() should be called in that case?
       if (err.extensions && err.extensions.serviceName) {
         return;
       }
@@ -101,10 +109,10 @@ export class EngineReportingTreeBuilder {
     error: Trace.Error,
   ) {
     if (!this.startHrTime) {
-      throw Error('addProtobufError called before startTiming!');
+      throw internalError('addProtobufError called before startTiming!');
     }
     if (this.stopped) {
-      throw Error('addProtobufError called after stopTiming!');
+      throw internalError('addProtobufError called after stopTiming!');
     }
 
     // By default, put errors on the root node.

packages/apollo-server-integration-testsuite/src/ApolloServer.ts

@@ -2027,6 +2027,7 @@ export function testApolloServer<AS extends ApolloServerBase>(
         type Query {
           books: [Book]
           movies: [Movie]
+          error: String
         }
       `;
 
@@ -2042,6 +2043,9 @@ export function testApolloServer<AS extends ApolloServerBase>(
             new Promise(resolve =>
               setTimeout(() => resolve([{ title: 'H' }]), 12),
             ),
+          error: () => {
+            throw new GraphQLError('It broke');
+          },
         },
       };
 
@@ -2089,10 +2093,6 @@ export function testApolloServer<AS extends ApolloServerBase>(
         });
 
         const apolloFetch = createApolloFetchAsIfFromGateway(uri);
-        apolloFetch.use(({ options }, next) => {
-          options.headers = { 'apollo-federation-include-trace': 'ftv1' };
-          next();
-        });
 
         const result = await apolloFetch({
           query: `{ books { title author } }`,
@@ -2129,6 +2129,43 @@ export function testApolloServer<AS extends ApolloServerBase>(
           );
         }
       });
+
+      it('includes errors in federated trace', async () => {
+        const { url: uri } = await createApolloServer({
+          typeDefs: allTypeDefs,
+          resolvers,
+          formatError(err) {
+            err.message = `Formatted: ${err.message}`;
+            return err;
+          },
+          engine: {
+            rewriteError(err) {
+              err.message = `Rewritten for Engine: ${err.message}`;
+              return err;
+            },
+          },
+        });
+
+        const apolloFetch = createApolloFetchAsIfFromGateway(uri);
+
+        const result = await apolloFetch({
+          query: `{ error }`,
+        });
+
+        expect(result.data).toStrictEqual({ error: null });
+        expect(result.errors).toBeTruthy();
+        expect(result.errors.length).toBe(1);
+        expect(result.errors[0].message).toBe('Formatted: It broke');
+
+        const ftv1: string = result.extensions.ftv1;
+
+        expect(ftv1).toBeTruthy();
+        const encoded = Buffer.from(ftv1, 'base64');
+        const trace = Trace.decode(encoded);
+        expect(trace.root.child[0].error[0].message).toBe(
+          'Rewritten for Engine: It broke',
+        );
+      });
     });
 
     describe('Response caching', () => {