Add timeouts to resolvers

.env.example

@@ -47,3 +47,4 @@ QUERY_DEPTH_LIMIT=10
 REQUEST_THROTTLE_MS=5000
 REQUEST_TIMEOUT_MS=5000
 RESIZING_SERVICE=gemini
+RESOLVER_TIMEOUT_MS=5000

package.json

@@ -72,6 +72,7 @@
     "graphql-tools": "^3.0.0",
     "graphql-type-json": "^0.1.4",
     "i": "^0.3.5",
+    "invariant": "^2.2.4",
     "jwt-simple": "^0.5.0",
     "lodash": "^4.3.0",
     "longjohn": "^0.2.12",
@@ -96,12 +97,14 @@
     "uuid": "^3.1.0"
   },
   "resolutions": {
-    "babel-core": "^7.0.0-bridge.0"
+    "babel-core": "^7.0.0-bridge.0",
+    "@types/graphql": "^0.13.1"
   },
   "devDependencies": {
     "@artsy/express-reloadable": "^1.3.0",
     "@types/express-graphql": "^0.0.35",
-    "@types/graphql": "^0.8.2",
+    "@types/graphql": "^0.13.1",
+    "@types/invariant": "^2.2.29",
     "@types/jest": "^22.2.3",
     "@types/lodash": "^4.14.74",
     "@types/moment": "^2.13.0",

src/config.js

@@ -51,6 +51,7 @@ const {
   REQUEST_THROTTLE_MS,
   REQUEST_TIMEOUT_MS,
   RESIZING_SERVICE,
+  RESOLVER_TIMEOUT_MS,
   SENTRY_PRIVATE_DSN,
 } = process.env
 
@@ -87,6 +88,8 @@ export default {
     Number(BIDDER_POSITION_MAX_BID_AMOUNT_CENTS_LIMIT) ||
     Number.MAX_SAFE_INTEGER,
   CACHE_LIFETIME_IN_SECONDS: Number(CACHE_LIFETIME_IN_SECONDS) || 2592000, // 30 days
+  CACHE_QUERY_LOGGING_THRESHOLD_MS:
+    Number(CACHE_QUERY_LOGGING_THRESHOLD_MS) || 1000,
   CACHE_RETRIEVAL_TIMEOUT_MS: Number(CACHE_RETRIEVAL_TIMEOUT_MS) || 2000,
   CONVECTION_API_BASE,
   CONVECTION_APP_ID,
@@ -131,8 +134,7 @@ export default {
   REDIS_URL,
   REQUEST_THROTTLE_MS: Number(REQUEST_THROTTLE_MS) || 5000,
   REQUEST_TIMEOUT_MS: Number(REQUEST_TIMEOUT_MS) || 5000,
-  CACHE_QUERY_LOGGING_THRESHOLD_MS:
-    Number(CACHE_QUERY_LOGGING_THRESHOLD_MS) || 1000,
   RESIZING_SERVICE,
+  RESOLVER_TIMEOUT_MS: Number(RESOLVER_TIMEOUT_MS) || 5000,
   SENTRY_PRIVATE_DSN,
 }

src/index.js

@@ -1,7 +1,8 @@
 /* eslint-disable no-console */
 
-import { middleware as requestTracer, traceMiddleware } from "./lib/tracer"
-import { applyMiddleware } from "graphql-middleware"
+import { middleware as requestTracer, traceMiddleware as graphqlTraceMiddleware } from "./lib/tracer"
+import { graphqlTimeoutMiddleware } from "./lib/graphqlTimeoutMiddleware"
+import { applyMiddleware as applyGraphQLMiddleware } from "graphql-middleware"
 
 import bodyParser from "body-parser"
 import config from "./config"
@@ -36,6 +37,7 @@ const {
   LOG_QUERY_DETAILS_THRESHOLD,
   NODE_ENV,
   QUERY_DEPTH_LIMIT,
+  RESOLVER_TIMEOUT_MS,
   SENTRY_PRIVATE_DSN,
 } = config
 const isProduction = NODE_ENV === "production"
@@ -51,7 +53,7 @@ function logQueryDetailsIfEnabled() {
   if (Number.isInteger(logQueryDetailsThreshold)) {
     console.warn(
       `[FEATURE] Enabling logging of queries running past the ${
-        logQueryDetailsThreshold
+      logQueryDetailsThreshold
       } sec threshold.`
     )
     return logQueryDetails(logQueryDetailsThreshold)
@@ -69,7 +71,7 @@ async function startApp() {
 
   if (enableQueryTracing) {
     console.warn("[FEATURE] Enabling query tracing")
-    schema = applyMiddleware(localSchema, traceMiddleware)
+    schema = applyGraphQLMiddleware(schema, graphqlTraceMiddleware)
     app.use(requestTracer)
   }
 
@@ -84,6 +86,8 @@ async function startApp() {
     }
   }
 
+  schema = applyGraphQLMiddleware(schema, graphqlTimeoutMiddleware(RESOLVER_TIMEOUT_MS))
+
   app.use(requestIDsAdder)
 
   if (enableSentry) {

src/lib/__tests__/graphqlTimeoutMiddleware.test.ts

@@ -0,0 +1,200 @@
+import { graphqlTimeoutMiddleware, fieldFromResolveInfo, timeoutForField } from "../graphqlTimeoutMiddleware"
+
+import { makeExecutableSchema, IResolvers } from "graphql-tools"
+import gql from "../../test/gql"
+import { graphql, buildSchema, GraphQLResolveInfo } from "graphql"
+import { applyMiddleware } from "graphql-middleware"
+
+/**
+ * Combined with async/await, this function can be used to simply add a delay
+ * between multiple expressions.
+ */
+function delay(by: number): Promise<void> {
+  return new Promise(resolve => setTimeout(resolve, by))
+}
+
+describe("graphQLTimeoutMiddleware", () => {
+  const defaultTimeout = 5
+  const artworkTimeout = defaultTimeout + 1
+
+  const typeDefs = gql`
+    directive @timeout(
+      ms: Int!
+    ) on FIELD_DEFINITION
+
+    schema {
+      query: Query
+    }
+
+    type Query {
+      artwork: Artwork @timeout(ms: ${artworkTimeout})
+    }
+
+    type Artwork {
+      artists: [Artist]
+      title: String
+    }
+
+    type Artist {
+      name: String
+    }
+  `
+
+  describe("fieldFromResolveInfo", () => {
+    it("returns the field definition for the field resolver", () => {
+      const schema = buildSchema(typeDefs)
+      const resolveInfo = {
+        fieldName: "artwork",
+        parentType: schema.getQueryType(),
+      } as GraphQLResolveInfo
+
+      const artworkField = schema.getQueryType()!.getFields().artwork
+      expect(fieldFromResolveInfo(resolveInfo)).toBe(artworkField)
+    })
+  })
+
+  describe("timeoutForField", () => {
+    function timeoutField(timeout: object | null) {
+      const args = timeout && Object.keys(timeout).map(key => `${key}: ${timeout[key]}`).join(", ")
+      const directive = timeout && `@timeout${args ? `(${args})` : ""}` || ""
+      const schema = buildSchema(gql`
+        schema {
+          query: Query
+        }
+        type Query {
+          field: String ${directive}
+        }
+      `)
+      return schema.getQueryType()!.getFields().field
+    }
+
+    it("returns null if there was no timeout specified", () => {
+      expect(timeoutForField(timeoutField(null))).toEqual(null)
+    })
+
+    it("returns the specified timeout", () => {
+      expect(timeoutForField(timeoutField({ ms: 42 }))).toEqual(42)
+    })
+
+    it("throws an error if the directive is specified but no ms argument is given", () => {
+      expect(() => timeoutForField(timeoutField({ sec: 42 }))).toThrowError(/argument is required/)
+    })
+
+    it("throws an error if the directive is specified but no integer argument is given", () => {
+      expect(() => timeoutForField(timeoutField({ ms: `"42"` }))).toThrowError(/Expected.+IntValue.+got.+StringValue/)
+    })
+  })
+
+  describe("execution", () => {
+    let resolvers: IResolvers
+
+    const responseData = {
+      title: "An artwork",
+      artists: [
+        { name: "An artist" },
+        { name: "Another artist" },
+      ],
+    }
+
+    function query() {
+      const schema = makeExecutableSchema({
+        typeDefs,
+        resolvers,
+      })
+      applyMiddleware(schema, graphqlTimeoutMiddleware(defaultTimeout))
+      return graphql(
+        schema,
+        gql`
+          query {
+            artwork {
+              title
+              artists {
+                name
+              }
+            }
+          }
+        `
+      )
+    }
+
+    it("resolves if execution does not take longer than the set timeout", async () => {
+      resolvers = {
+        Query: {
+          artwork: () => responseData,
+        },
+      }
+      expect(await query()).toEqual({
+        data: {
+          artwork: responseData,
+        },
+      })
+    })
+
+    it("returns `null` if execution of resolver with specific timeout takes longer than the set timeout", async () => {
+      resolvers = {
+        Query: {
+          // Time out by going over the artworkTimeout
+          artwork: async () => {
+            await delay(artworkTimeout + 2)
+            return responseData
+          }
+        },
+      }
+      const response = await query()
+      expect(response.data).toEqual({ artwork: null })
+      expect(response.errors!.length).toEqual(1)
+      expect(response.errors![0].message).toMatch(
+        /GraphQL Error: Query\.artwork has timed out after waiting for \d+ms/
+      )
+    })
+
+    it("returns `null` if execution of resolvers takes longer than their timeout", async () => {
+      resolvers = {
+        Query: {
+          artwork: () => ({}),
+        },
+        Artwork: {
+          title: () => responseData.title,
+          artists: () => [{}, {}],
+        },
+        Artist: {
+          name: async () => {
+            await delay(defaultTimeout + 2)
+            return "Some artist"
+          }
+        }
+      }
+      const response = await query()
+      expect(response.data).toEqual({
+        artwork: {
+          title: responseData.title,
+          artists: [{ name: null }, { name: null }]
+        }
+      })
+      expect(response.errors!.length).toEqual(2)
+      expect(response.errors![0].message).toMatch(
+        /GraphQL Error: Artist\.name has timed out after waiting for \d+ms/
+      )
+    })
+
+    it("once a resolver timeout has passed, no nested resolvers will be invoked", async () => {
+      const nestedResolver = jest.fn()
+      resolvers = {
+        Query: {
+          // Time out by going over the artworkTimeout
+          artwork: async () => {
+            await delay(artworkTimeout + 2)
+            return responseData
+          }
+        },
+        Artist: {
+          // This resolver should not be called once the above has timed out
+          name: nestedResolver,
+        }
+      }
+      await query()
+      await delay(artworkTimeout + 4)
+      expect(nestedResolver).not.toBeCalled()
+    })
+  })
+})

src/lib/graphqlErrorHandler.js

@@ -40,6 +40,7 @@ export default function graphqlErrorHandler(
     return {
       message: error.message,
       locations: error.locations,
+      path: isProduction ? null : error.path,
       stack: isProduction ? null : error.stack,
     }
   }

src/lib/graphqlTimeoutMiddleware.ts

@@ -0,0 +1,49 @@
+import { IMiddleware } from "graphql-middleware"
+import { GraphQLResolveInfo, GraphQLField } from "graphql"
+import invariant from "invariant"
+
+export function fieldFromResolveInfo(resolveInfo: GraphQLResolveInfo) {
+  return resolveInfo.parentType.getFields()[resolveInfo.fieldName]
+}
+
+export function timeoutForField(field: GraphQLField<any, any>) {
+  const fieldDirectives = field.astNode && field.astNode.directives
+  const directive = fieldDirectives && fieldDirectives.find(directive => directive.name.value === "timeout")
+  if (directive) {
+    const args = directive && directive.arguments
+    const arg = args && args[0]
+    invariant(arg && arg.name.value === "ms", "graphqlTimeoutMiddleware: The `@timeout(ms: …)` argument is required.")
+    const value = arg!.value
+    if (value.kind === "IntValue") {
+      return parseInt(value.value)
+    } else {
+      invariant(false, `graphqlTimeoutMiddleware: Expected \`@timeout(ms: …)\` to be a \`IntValue\`, got \`${value.kind}\` instead.`)
+      return null
+    }
+  }
+  return null
+}
+
+export const graphqlTimeoutMiddleware = (defaultTimeoutInMS: number) => {
+  const middleware: IMiddleware = (
+    middlewareResolver,
+    parent,
+    args,
+    context,
+    info
+  ) => {
+    // TODO: Maybe cache if it turns out to take significant time.
+    //       Should probably be cached on the schema instance.
+    const timeoutInMS = timeoutForField(fieldFromResolveInfo(info)) || defaultTimeoutInMS
+    return Promise.race([
+      new Promise((_resolve, reject) => {
+        setTimeout(() => {
+          const field = `${info.parentType}.${info.fieldName}`;
+          reject(new Error(`GraphQL Error: ${field} has timed out after waiting for ${timeoutInMS}ms`))
+        }, timeoutInMS)
+      }),
+      new Promise(resolve => resolve(middlewareResolver(parent, args, context, info))),
+    ])
+  }
+  return middleware
+}