diff --git a/CHANGELOG.md b/CHANGELOG.md index 9151f21f5eb..1ba960b5d19 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,10 @@ The version headers in this history reflect the versions of Apollo Server itself - [`@apollo/gateway`](https://github.com/apollographql/federation/blob/HEAD/gateway-js/CHANGELOG.md) - [`@apollo/federation`](https://github.com/apollographql/federation/blob/HEAD/federation-js/CHANGELOG.md) +## vNEXT + +- `apollo-server-core`: Fix usage reporting plugin "willResolveField called after stopTiming!" error caused by a race condition related to null bubbling. [Issue #4472](https://github.com/apollographql/apollo-server/issues/4472) [PR #6398](https://github.com/apollographql/apollo-server/pull/6398) + ## v3.8.1 - This is a patch release strictly for republishing over what appears to be a hiccup in NPMs service. [Issue #6469](https://github.com/apollographql/apollo-server/issues/6469) diff --git a/packages/apollo-server-core/src/plugin/traceTreeBuilder.ts b/packages/apollo-server-core/src/plugin/traceTreeBuilder.ts index 9adee45a45b..71bc52578bd 100644 --- a/packages/apollo-server-core/src/plugin/traceTreeBuilder.ts +++ b/packages/apollo-server-core/src/plugin/traceTreeBuilder.ts @@ -68,7 +68,49 @@ export class TraceTreeBuilder { throw internalError('willResolveField called before startTiming!'); } if (this.stopped) { - throw internalError('willResolveField called after stopTiming!'); + // We've been stopped, which means execution is done... and yet we're + // still resolving more fields? How can that be? Shouldn't we throw an + // error or something? + // + // Well... we used to do exactly that. But this "shouldn't happen" error + // showed up in practice! Turns out that graphql-js can actually continue + // to execute more fields indefinitely long after `execute()` resolves! + // That's because parallelism on a selection set is implemented using + // `Promise.all`, and as soon as one of its arguments (ie, one field) + // throws an error, the combined Promise resolves, but there's no + // "cancellation" of the Promises that are the other arguments to + // `Promise.all`. So the code contributing to those Promises keeps on + // chugging away indefinitely. + // + // Concrete example: let’s say you have + // + // { x y { ARBITRARY_SELECTION_SET } } + // + // where x has a non-null return type, and x and y both have resolvers + // that return Promises. And let’s say that x returns a Promise that + // rejects (or resolves to null). What this means is that we’re going to + // eventually end up with `data: null` (nothing under y will actually + // matter), but graphql-js execution will continue running whatever is + // under ARBITRARY_SELECTION_SET without any sort of short circuiting. In + // fact, the Promise returned from execute itself can happily resolve + // while execution is still chugging away on an arbitrary amount of fields + // under that ARBITRARY_SELECTION_SET. There’s no way to detect from the + // outside "all the execution related to this operation is done", nor to + // "short-circuit" execution so that it stops going. + // + // So, um. We will record any field whose execution we manage to observe + // before we "stop" the TraceTreeBuilder (whether it is one that actually + // ends up in the response or whether it gets thrown away due to null + // bubbling), but if we get any more fields afterwards, we just ignore + // them rather than throwing a confusing error. + // + // (That said, the error we used to throw here generally was hidden + // anyway, for the same reason: it comes from a branch of execution that + // ends up not being included in the response. But + // https://github.com/graphql/graphql-js/pull/3529 means that this + // sometimes crashed execution anyway. Our error never caught any actual + // problematic cases, so keeping it around doesn't really help.) + return () => {}; } const path = info.path;