apollo-engine-reporting: fix reporting errors from backends (#3056)

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.

CHANGELOG.md

@@ -6,6 +6,7 @@ The version headers in this history reflect the versions of Apollo Server itself
 
 > The changes noted within this `vNEXT` section have not been released yet.  New PRs and commits which introduce changes should include an entry in this `vNEXT` section as part of their development.  When a release is being prepared, a new header will be (manually) created below and the the appropriate changes within that release will be moved into the new section.
 
+- `apollo-engine-reporting`: fix reporting errors from backend. (The support for federated metrics introduced in v2.7.0 did not properly handle GraphQL errors from the backend; all users of federated metrics should upgrade to this version.) [PR #3056](https://github.com/apollographql/apollo-server/pull/3056) [Issue #3052](https://github.com/apollographql/apollo-server/issues/3052)
 - `apollo-engine-reporting`: clean up `SIGINT` and `SIGTERM` handlers when `EngineReportingAgent` is stopped; fixes 'Possible EventEmitter memory leak detected' log. [PR #3090](https://github.com/apollographql/apollo-server/pull/3090)
 
 ### v2.7.1

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)! See #3091.
   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.