apollo-server-core 2.9.14 breaks APQ usage

[tapsboy]

My GraphQL App server depends on apollo-server-express which I recently updated to 2.9.14 (which in turn resolves apollo-server-core 2.9.14). Upon updating to this version, my APQ queries started failing, with an internal error 500 as the response:

{
	"errors": [{
		"message": "[internal apollo-server error] addProtobufError called before startTiming!",
		"extensions": {
			"code": "INTERNAL_SERVER_ERROR",
			"exception": {
				"stacktrace": ["Error: 
[internal apollo-server error] addProtobufError called before startTiming!", "    
at internalError (/path-to-dir/node_modules/apollo-engine-reporting/dist/treeBuilder.js:6:12)", "    
at EngineReportingTreeBuilder.addProtobufError (/path-to-dir/node_modules/apollo-engine-reporting/dist/treeBuilder.js:72:19)", "    
at /path-to-dir/node_modules/apollo-engine-reporting/dist/treeBuilder.js:67:18", "    
at Array.forEach (<anonymous>)", "    
at EngineReportingTreeBuilder.didEncounterErrors (/path-to-dir/node_modules/apollo-engine-reporting/dist/treeBuilder.js:59:16)", "    
at EngineReportingExtension.didEncounterErrors (/path-to-dir/node_modules/apollo-engine-reporting/dist/extension.js:84:26)", "    
at /path-to-dir/node_modules/graphql-extensions/dist/index.js:29:27", "    
at Array.forEach (<anonymous>)", "    
at GraphQLExtensionStack.didEncounterErrors (/path-to-dir/node_modules/graphql-extensions/dist/index.js:27:25)", "    
at /path-to-dir/node_modules/apollo-server-core/dist/requestPipeline.js:268:32"
]
			}
		}
	}]
}

My expected response was:

{
	"errors": [{
		"message": "PersistedQueryNotFound",
		"extensions": {
			"code": "PERSISTED_QUERY_NOT_FOUND",
			"exception": {
				"stacktrace": [
"PersistedQueryNotFoundError: PersistedQueryNotFound", "    
at Object.<anonymous> (/path-to-dir/node_modules/apollo-server-core/dist/requestPipeline.js:75:52)", "    
at Generator.next (<anonymous>)", "    
at fulfilled (/path-to-dir/node_modules/apollo-server-core/dist/requestPipeline.js:5:58)", "    
at <anonymous>", "   
at process._tickCallback (internal/process/next_tick.js:189:7)"]
			}
		}
	}]
}

Upon further reading of code, I found this PR that changes the server-core and might be influencing the behavior: dcbbc34

I am not sure if I am doing something wrong on the Apollo Client side, but

A prior release tag of app included 2.9.13 for both apollo-server-express and apollo-server-core works fine. My temp fix involved was to get that package-lock from that tag to ensure that it worked.

Note: Manually edited the error responses for easy reading and to redact private path structures

[eugene1g]

Having the same issue - we're using APQ ("persisted queries") on the frontend, so all GraphQL queries 'fail' for the first time (because the request is a hash of the query, and not the full query). The recent PT #3614 ensured that these errors show up as exceptions in the request pipeline of Apollo, but seems like error-handling logic should be expanded to... start the timer? Not sure. Our solution was to disable this feature in the frontend app for now.

Paging @abernix and @trevor-scheer as APQ & 2.9.14 is currently an unhappy duo :)

[suciuvlad]

+1

[abernix]

Thanks for reporting this! It appears as if this could be related to an unexpected condition within Apollo Engine Reporting (i.e. apollo-engine-reporting), in which the didEncounterErrors is now getting fired before previously expected. Could someone experiencing the problem try and see if the APQ behavior works normally when Apollo Graph Manager (a.k.a. Engine) reporting functionality is disabled by setting engine: false?

[abernix]

This should be fixed by #3638, which I just released in v2.9.15.

[eugene1g]

Thanks @abernix - v2.9.15 fixed it for me. Thank you for such a quick patch over the holidays!

[abernix]

Thanks for feedback confirming that it’s fixed!

[abbashassanali]

Hi. Seeing this error again in 2.11.0 It seems to throw even if engine is set to false.

errors": [ { "message": "[internal apollo-server error] addProtobufError called before startTiming!", "extensions": { "code": "INTERNAL_SERVER_ERROR", "exception": { "stacktrace": [ "Error: [internal apollo-server error] addProtobufError called before startTiming!", " at internalError (/var/task/node_modules/apollo-engine-reporting/dist/treeBuilder.js:8:12)", " at EngineReportingTreeBuilder.addProtobufError (/var/task/node_modules/apollo-engine-reporting/dist/treeBuilder.js:79:19)", " at /var/task/node_modules/apollo-engine-reporting/dist/treeBuilder.js:74:18", " at Array.forEach (<anonymous>)", " at EngineReportingTreeBuilder.didEncounterErrors (/var/task/node_modules/apollo-engine-reporting/dist/treeBuilder.js:61:16)", " at EngineReportingExtension.didEncounterErrors (/var/task/node_modules/apollo-engine-reporting/dist/extension.js:84:26)", " at /var/task/node_modules/graphql-extensions/dist/index.js:29:27", " at Array.forEach (<anonymous>)", " at GraphQLExtensionStack.didEncounterErrors (/var/task/node_modules/graphql-extensions/dist/index.js:27:25)", " at /var/task/node_modules/apollo-server-core/dist/requestPipeline.js:273:32", " at Generator.next (<anonymous>)", " at /var/task/node_modules/apollo-server-core/dist/requestPipeline.js:8:71", " at new Promise (<anonymous>)", " at __awaiter (/var/task/node_modules/apollo-server-core/dist/requestPipeline.js:4:12)", " at didEncounterErrors (/var/task/node_modules/apollo-server-core/dist/requestPipeline.js:271:20)", " at /var/task/node_modules/apollo-server-core/dist/requestPipeline.js:266:23" ] } } } ]

[thaoabunga]

@abbashassanali Could you please provide us with a running reproduction? Thank you! cc: @trevor-scheer

[abernix]

@abbashassanali If anyone can provide a reproduction for this problem, please do so in #3978. Locking this issue to prevent upvotes from accumulating on this closed issue, and rather encourage those up-voters to provide reproduction steps.