apollo-engine-reporting: fix reporting errors from backends

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.