Repository: newrelic/newrelic-node-apollo-server-plugin (js)

Issue:
Generic POST//graphql appears after running web server for a while
## Description

Hey all, I'm running into a weird issue and was wondering if this is the right place to ask. A couple days ago, I integrated this plugin with our new relic integration (we use Apollo Server with express). Everything appeared to be working, but I noticed that after our servers run for a couple hours, performance seems to "degrade" according to new relic. When I look at the top most time consuming transaction, I see that it's a generic `post` to `/graphql`. 

<img width="359" alt="perf-issues-screenshot" src="https://user-images.githubusercontent.com/5010246/125696416-3c3c3296-435d-4539-9e6c-735ad301c98f.png">

When I dive into the segment trace for this generic post, I see that it's the amalgamation of all our graphql resolvers (this continued for many more segments) 

<img width="886" alt="Screen Shot 2021-07-14 at 5 24 05 PM" src="https://user-images.githubusercontent.com/5010246/125696591-3745c23e-0a15-4ce5-b6e6-52fa80ffc564.png">

What I find even odder is that when we deploy and new code starts running on our servers, is that this generic post on our top most time consumings transactions completely goes away for a couple hours and then comes back. (Screenshot below from 30 mins after fresh deploy). 

<img width="367" alt="non-perf-issues-screenshot" src="https://user-images.githubusercontent.com/5010246/125696935-e4ff998f-00b5-4aa7-b6f4-deb17d40a872.png">

As far as I can tell, nothing in our code calls all the resolvers at the same time. So my question is, is this expected behavior? Are we doing something wrong on our side? If it is expected,  why wouldn't this new relic transaction have an end depth like all the others? Also if so, is there a way to ignore it if it's not actually affecting perf? My goal here is to figure out if this is actually a server perf issue and fix it or it ignore it depending on what I learn here. Many thanks in advance. 

- Alex

## Expected Behavior

Generic `post//graphql` to not show up in our new relic transactions and instead show each individual transaction. 

## Steps to Reproduce

Install new relic, use Apollo express, add this as a plugin (as far as I can tell). 

## Your Environment

newrelic version 6.13.2
newrelic/apollo-server-plugin version  0.3.0
Node Version v12.13.1
Running on [heroku stack 18](https://devcenter.heroku.com/articles/heroku-18-stack)





Pull request description:
Name operation segment earlier
<!--
Thank you for submitting a Pull Request.

This code is leveraged to monitor critical services. Please consider the following:
* Tests are required.
* Performance matters.
* Features that are specific to just your app are unlikely to make it in.

Please fill out the relevant sections as follows:
* Proposed Release Notes: Bulleted list of recommended release notes for the change(s).
* Links: Any relevant links for the change.
* Details: In-depth description of changes, other technical notes, etc.
-->

## Proposed Release Notes
 * Moved naming of operation segment and updating transaction to `validationDidStart` phase of Apollo Server request.

## Links
Closes #117

## Details
I was able to reproduce the bug #117 by employing the brute force method @carlo-808 mentioned with `connect-timeout`.  So it appears if you initiate an apollo server request but throw some error out of band where apollo does not emit the `didEncounterErrors` hook you get into this situation.  So in the `connect-timeout` case, that middleware will emit a timeout after n milliseconds.  That timeout is not being caught by apollo thus not allowing `didEncounterErrors` and subsequently `willSendResponse` hooks to fire. We were updating the name of the operation segment and transaction in the `willSendResponse`.  There was no reason aside from we had the most information but the only information we need now that we refactored finding the deepest path and naming is from the graphql document AST.  The first time this is available is in `validationDidStart`, hence the PR.



Patch:
diff --git a/lib/create-plugin.js b/lib/create-plugin.js
index 32f17f0..4ea93fa 100644
--- a/lib/create-plugin.js
+++ b/lib/create-plugin.js
@@ -12,7 +12,6 @@ const cleanQuery = require('./query-utils')
 const NOTICED_ERRORS = ErrorHelper.NOTICED_ERRORS
 
 const ANON_PLACEHOLDER = '<anonymous>'
-const UNKNOWN_OPERATION = '<unknown>'
 
 const CATEGORY = 'GraphQL'
 const FRAMEWORK = 'ApolloServer'
@@ -20,6 +19,8 @@ const OPERATION_PREFIX = CATEGORY + '/operation/' + FRAMEWORK
 const RESOLVE_PREFIX = CATEGORY + '/resolve/' + FRAMEWORK
 const BATCH_PREFIX = 'batch'
 
+const DEFAULT_OPERATION_NAME = `${OPERATION_PREFIX}/<unknown>`
+
 const FIELD_NAME_ATTR = 'graphql.field.name'
 const RETURN_TYPE_ATTR = 'graphql.field.returnType'
 const PARENT_TYPE_ATTR = 'graphql.field.parentType'
@@ -86,7 +87,7 @@ function createPlugin(instrumentationApi, config = {}) {
       // We do not set to active here as batched queries will hit this
       // back to back and we'd prefer those not nest with each-other.
       const operationSegment = instrumentationApi.createSegment(
-        UNKNOWN_OPERATION,
+        DEFAULT_OPERATION_NAME,
         recordOperationSegment,
         requestParent
       )
@@ -99,6 +100,38 @@ function createPlugin(instrumentationApi, config = {}) {
       operationSegment.start()
 
       return {
+        /**
+         * The document AST has been parsed so we can attempt to name the operation
+         * and update the transaction name based on operation
+         */
+        validationDidStart(validationContext) {
+          const operationDetails = getOperationDetails(validationContext)
+          if (operationDetails) {
+            const { operationName, operationType, deepestUniquePath, cleanedQuery } =
+              operationDetails
+
+            operationSegment.addAttribute(OPERATION_QUERY_ATTR, cleanedQuery)
+
+            operationSegment.addAttribute(OPERATION_TYPE_ATTR, operationType)
+
+            if (operationName) {
+              operationSegment.addAttribute(OPERATION_NAME_ATTR, operationName)
+            }
+
+            const formattedName = operationName || ANON_PLACEHOLDER
+            let formattedOperation = `${operationType}/${formattedName}`
+
+            // Certain requests, such as introspection, won't hit any resolvers
+            if (deepestUniquePath) {
+              formattedOperation += `/${deepestUniquePath}`
+            }
+
+            const segmentName = formattedOperation
+            const transactionName = formattedOperation
+            setTransactionName(operationSegment.transaction, transactionName)
+            operationSegment.name = `${OPERATION_PREFIX}/${segmentName}`
+          }
+        },
         didResolveOperation(resolveContext) {
           if (shouldIgnoreTransaction(resolveContext.operation, config, logger)) {
             const activeSegment = instrumentationApi.getActiveSegment()
@@ -184,39 +217,12 @@ function createPlugin(instrumentationApi, config = {}) {
             }
           }
         },
-        willSendResponse(responseContext) {
-          // default. only used if failed to parse
-          let transactionName = '*'
-          let segmentName = UNKNOWN_OPERATION
-
-          const operationDetails = getOperationDetails(responseContext)
-          if (operationDetails) {
-            const { operationName, operationType, deepestUniquePath, cleanedQuery } =
-              operationDetails
-
-            operationSegment.addAttribute(OPERATION_QUERY_ATTR, cleanedQuery)
-
-            operationSegment.addAttribute(OPERATION_TYPE_ATTR, operationType)
-
-            if (operationName) {
-              operationSegment.addAttribute(OPERATION_NAME_ATTR, operationName)
-            }
-
-            const formattedName = operationName || ANON_PLACEHOLDER
-            let formattedOperation = `${operationType}/${formattedName}`
-
-            // Certain requests, such as introspection, won't hit any resolvers
-            if (deepestUniquePath) {
-              formattedOperation += `/${deepestUniquePath}`
-            }
-
-            segmentName = formattedOperation
-            transactionName = formattedOperation
+        willSendResponse() {
+          // check if operation segment was never updated from default name
+          // If so, update the transaction name to `*`
+          if (operationSegment.name === DEFAULT_OPERATION_NAME) {
+            setTransactionName(operationSegment.transaction, '*')
           }
-
-          setTransactionName(operationSegment.transaction, transactionName)
-
-          operationSegment.name = `${OPERATION_PREFIX}/${segmentName}`
           operationSegment.end()
 
           logger.trace('End willSendResponse')


Test patch:
diff --git a/tests/unit/create-plugin.test.js b/tests/unit/create-plugin.test.js
index c360f82..1bf9e5f 100644
--- a/tests/unit/create-plugin.test.js
+++ b/tests/unit/create-plugin.test.js
@@ -33,7 +33,10 @@ tap.test('createPlugin edge cases', (t) => {
         }
       },
       getActiveSegment: sinon.stub().returns({}),
-      createSegment: sinon.stub().returns(operationSegment),
+      createSegment: sinon.stub().callsFake((name) => {
+        operationSegment.name = name
+        return operationSegment
+      }),
       setActiveSegment: sinon.stub()
     }
   })
@@ -54,7 +57,7 @@ tap.test('createPlugin edge cases', (t) => {
 
     const hooks = createPlugin(instrumentationApi)
     const operationHooks = hooks.requestDidStart({})
-    operationHooks.willSendResponse(responseContext)
+    operationHooks.validationDidStart(responseContext)
     t.equal(
       operationSegment.name,
       'GraphQL/operation/ApolloServer/undefined/<anonymous>',
@@ -63,15 +66,20 @@ tap.test('createPlugin edge cases', (t) => {
     t.end()
   })
 
-  t.test('should not set operation name to unknown when document is null', (t) => {
+  t.test('should not update operation name when document is null', (t) => {
     const responseContext = {}
     const hooks = createPlugin(instrumentationApi)
     const operationHooks = hooks.requestDidStart({})
-    operationHooks.willSendResponse(responseContext)
     t.equal(
       operationSegment.name,
       'GraphQL/operation/ApolloServer/<unknown>',
-      'should set operation to unknown'
+      'should default operation name'
+    )
+    operationHooks.validationDidStart(responseContext)
+    t.equal(
+      operationSegment.name,
+      'GraphQL/operation/ApolloServer/<unknown>',
+      'should not update operation name'
     )
     t.end()
   })