Fix Apollo server error reporting

Ensure `setRoot` sets an active scope. If there is no active
scope, calling `scopeManager.setRoot` will set the given root
span as both the active span and the root span for the current
process. This fixes a bug where processes lose track of their
root span after `tracer.withSpan` is called.

Remove a check in the HTTP outgoing instrumentation that checks
if there is a current span before creating a root span.

Add integration tests for the current behaviour of the Apollo
Server integration. It can report a successful query, including
the query body, and report errors that take place during the
parsing and validation stages.

The error reporting was previously not working due to the bug
described above regarding `scopeManager.setRoot`.

packages/apollo-server/.changesets/fix-error-reporting.md

@@ -0,0 +1,6 @@
+---
+bump: "patch"
+type: "fix"
+---
+
+Fix error reporting. Due to a bug in the scope management logic, errors emitted by Apollo Server were not being reported by the integration.

packages/apollo-server/test/example/index.js

@@ -1,6 +1,6 @@
 const { Appsignal } = require("../../../nodejs")
 
-new Appsignal({
+const appsignal = new Appsignal({
   active: true,
   name: "<YOUR APPLICATION NAME>",
   pushApiKey: "<YOUR API KEY>"
@@ -47,9 +47,13 @@ const resolvers = {
   }
 }
 
+const { createApolloPlugin } = require("../../../apollo-server")
+
+const plugins = [createApolloPlugin(appsignal)]
+
 // The ApolloServer constructor requires two parameters: your schema
 // definition and your set of resolvers.
-const server = new ApolloServer({ typeDefs, resolvers })
+const server = new ApolloServer({ typeDefs, resolvers, plugins })
 
 // The `listen` method launches a web server.
 server.listen({ port: 4010 }).then(({ url }) => {

packages/apollo-server/test/spec/integration_spec.rb

@@ -1,10 +1,11 @@
 # frozen_string_literal: true
 
 require "net/http"
+require "json"
 
 EXAMPLE_APP_DIR = File.expand_path(File.join("..", "example"), __dir__)
 
-RSpec.describe "Next.js" do
+RSpec.describe "Apollo Server" do
   before(:context) do
     @app = AppRunner.new("npm run start", EXAMPLE_APP_DIR)
     @app.run
@@ -13,22 +14,112 @@
   after(:context) { @app.stop }
   after { @app.cleanup }
 
-  describe "POST /" do
-    before do
-      uri = URI("http://localhost:4010/")
-      http = Net::HTTP.new(uri.host, uri.port)
-      request = Net::HTTP::Post.new(uri.request_uri)
-      request["Content-Type"] = "application/json"
-      request.body = '{"query":"query { __typename }"}'
-      @response = http.request(request).body
-    end
-
-    it "sets the root span's name" do
-      expect(@response).to match('{"data":{"__typename":"Query"}}')
-
-      log = @app.logs
-      span_id = fetch_root_span_id(log)
-      expect(log).to include("Set name 'POST /' for span '#{span_id}'")
-    end
+  def request_query(query)
+    uri = URI("http://localhost:4010/")
+    http = Net::HTTP.new(uri.host, uri.port)
+    request = Net::HTTP::Post.new(uri.request_uri)
+    request["Content-Type"] = "application/json"
+    request.body = { "query" => query }.to_json
+    http.request(request)
+  end
+
+  it("reports a successful query") do
+    query = "query AllTheBooks { books { title } }"
+    response = request_query(query)
+    expect(response.code).to eq("200")
+
+    log = @app.logs
+
+    root_span_id = fetch_root_span_id(log)
+    expect(log).to include("Set name 'AllTheBooks' for span '#{root_span_id}'")
+
+    child_span_ids = fetch_child_span_ids(log, root_span_id)
+    expect(child_span_ids.length).to be(3)
+
+    parse_span_id, validate_span_id, execute_span_id = child_span_ids
+
+    expect(log).to include(
+      "Set attribute for key 'appsignal:category' " \
+        "with value 'parse.graphql' to span '#{parse_span_id}'"
+    )
+    expect(log).to include(
+      "Set attribute for key 'appsignal:category' " \
+        "with value 'validate.graphql' to span '#{validate_span_id}'"
+    )
+    expect(log).to include(
+      "Set attribute for key 'appsignal:category' " \
+        "with value 'execute.graphql' to span '#{execute_span_id}'"
+    )
+    expect(log).to include(
+      "Set attribute for key 'appsignal:body' " \
+        "with value '#{query}' to span '#{execute_span_id}'"
+    )
+  end
+
+  it("reports an error when a query fails to parse") do
+    query = "gibberish"
+    response = request_query(query)
+    expect(response.code).to eq("400")
+
+    log = @app.logs
+
+    root_span_id = fetch_root_span_id(log)
+    expect(log).to include("Set name '[unknown graphql query]' for span '#{root_span_id}'")
+
+    expect(log).to include(
+      "Add error 'GraphQLError' to span '#{root_span_id}' with message " \
+        "'Syntax Error: Unexpected Name \"gibberish\".' with a backtrace"
+    )
+
+    child_span_ids = fetch_child_span_ids(log, root_span_id)
+    expect(child_span_ids.length).to be(1)
+
+    parse_span_id = child_span_ids.first
+
+    expect(log).to include(
+      "Set attribute for key 'appsignal:category' " \
+        "with value 'parse.graphql' to span '#{parse_span_id}'"
+    )
+
+    expect(log).not_to include(
+      "Set attribute for key 'appsignal:category' with value 'validate.graphql'"
+    )
+    expect(log).not_to include(
+      "Set attribute for key 'appsignal:category' with value 'execute.graphql'"
+    )
+  end
+
+  it("reports an error when a query fails to validate") do
+    query = "query { books { cover } }"
+    response = request_query(query)
+    expect(response.code).to eq("400")
+
+    log = @app.logs
+
+    root_span_id = fetch_root_span_id(log)
+    expect(log).to include("Set name '[unknown graphql query]' for span '#{root_span_id}'")
+
+    expect(log).to include(
+      "Add error 'GraphQLError' to span '#{root_span_id}' with message " \
+        "'Cannot query field \"cover\" on type \"Book\".' with a backtrace"
+    )
+
+    child_span_ids = fetch_child_span_ids(log, root_span_id)
+    expect(child_span_ids.length).to be(2)
+
+    parse_span_id, validate_span_id = child_span_ids
+
+    expect(log).to include(
+      "Set attribute for key 'appsignal:category' " \
+        "with value 'parse.graphql' to span '#{parse_span_id}'"
+    )
+    expect(log).to include(
+      "Set attribute for key 'appsignal:category' " \
+        "with value 'validate.graphql' to span '#{validate_span_id}'"
+    )
+
+    expect(log).not_to include(
+      "Set attribute for key 'appsignal:category' with value 'execute.graphql'"
+    )
   end
 end

packages/nodejs/.changesets/ensure-the-root-span-is-preserved-across-scopes.md

@@ -0,0 +1,6 @@
+---
+bump: "patch"
+type: "fix"
+---
+
+Ensure the root span is preserved across scopes. Due to a bug in the scope management logic, calling `tracer.withSpan` could cause the root span for a given scope to be forgotten.

packages/nodejs/src/__tests__/scope.test.ts

@@ -32,6 +32,29 @@ describe("ScopeManager", () => {
     })
   })
 
+  describe(".setRoot()", () => {
+    it("sets the root span and active span for the current process", () => {
+      const span = new RootSpan()
+
+      scopeManager.setRoot(span)
+
+      expect(scopeManager.root()).toStrictEqual(span)
+      expect(scopeManager.active()).toStrictEqual(span)
+    })
+
+    describe("when there is an active span", () => {
+      it("does not set the active span for the current process", () => {
+        const rootSpan = new RootSpan()
+        const childSpan = new ChildSpan(rootSpan)
+
+        scopeManager.withContext(childSpan, () => {
+          scopeManager.setRoot(rootSpan)
+          expect(scopeManager.active()).toStrictEqual(childSpan)
+        })
+      })
+    })
+  })
+
   describe(".withContext()", () => {
     it("should run the callback (object as target)", () => {
       const fn = jest.fn(() => {

packages/nodejs/src/instrumentation/http/lifecycle/outgoing.ts

@@ -4,12 +4,10 @@
  * Copyright 2019, OpenTelemetry Authors
  */
 
-import { Tracer, Span } from "../../../interfaces"
+import { Tracer } from "../../../interfaces"
 import url from "url"
 import { IncomingMessage, ClientRequest, RequestOptions } from "http"
 
-import { NoopSpan } from "../../../noops"
-
 type HttpRequestArgs = Array<
   (
     res: IncomingMessage
@@ -72,7 +70,6 @@ function outgoingRequestFunction(
     urlOrOptions: string | url.URL | RequestOptions,
     ...args: unknown[]
   ): ClientRequest {
-    let span: Span
     let origin: string
     let method: string
 
@@ -91,14 +88,8 @@ function outgoingRequestFunction(
       return original.apply(this, [urlOrOptions, ...args])
     }
 
-    if (tracer.currentSpan() instanceof NoopSpan) {
-      // create a new `RootSpan` if there isn't one already in progress
-      span = tracer.createSpan()
-    } else {
-      span = tracer.currentSpan().child()
-    }
-
-    span
+    const span = tracer
+      .createSpan()
       .setName(`${method} ${origin}`)
       .setCategory("request.http")
       .set("method", method)

packages/nodejs/src/scope.ts

@@ -117,6 +117,9 @@ export class ScopeManager {
   public setRoot(rootSpan: Span) {
     const uid = asyncHooks.executionAsyncId()
     this.#roots.set(uid, rootSpan)
+    if (!this.#scopes.has(uid)) {
+      this.#scopes.set(uid, rootSpan)
+    }
   }
 
   /*

test/integration/support/integration_helper.rb

@@ -7,4 +7,8 @@ def fetch_root_span_id(log)
 
     span_id
   end
+
+  def fetch_child_span_ids(log, root_span_id)
+    log.scan(/Start child span '(\w+)' with parent '#{root_span_id}'/).map(&:first)
+  end
 end