Apollo Server / Envelop enhancements: logging, tracing, e2e tests (re…

…dwoodjs#2914)

* Adds tracing, logging & more to both graphqls

* Get to green and update e2e

* use git to rollback before tutorial-envelop

* init git in E2E Workflow file

* Rework logging, error handing, tracing, masking

* No longer need fromGraphQLError

* Setup depth limits on ApolloServer.

* Fix formatError test logic

* Add logger config, plugins, rules.

* upgrade related packages

Co-authored-by: David S Price <[email protected]>

.github/workflows/e2e.yaml

@@ -41,6 +41,12 @@ jobs:
       - name: Create a RedwoodJS app
         run: ./tasks/run-e2e ${{ steps.createpath.outputs.project_path }} --no-start
 
+      - name: Init Git for RedwoodJS app directory
+        run: |
+          git init --initial-branch main && git add .
+          git commit -a --message=init
+        working-directory: ${{ steps.createpath.outputs.project_path }}
+
       - name: Start server in background
         run: yarn rw dev --no-generate --fwd="--open=false" &
         working-directory: ${{ steps.createpath.outputs.project_path }}

packages/api/package.json

@@ -13,23 +13,27 @@
     "@graphql-tools/merge": "6.2.14",
     "@prisma/client": "2.25.0",
     "@types/pino": "6.3.8",
-    "apollo-server-lambda": "2.25.0",
+    "apollo-server-lambda": "2.25.2",
     "core-js": "3.13.1",
-    "graphql": "15.5.0",
-    "graphql-scalars": "1.9.3",
+    "graphql": "15.5.1",
+    "graphql-depth-limit": "^1.1.0",
+    "graphql-scalars": "1.10.0",
     "jsonwebtoken": "8.5.1",
     "jwks-rsa": "1.8.1",
     "lodash.merge": "4.6.2",
     "lodash.omitby": "4.6.0",
     "pino": "6.11.3",
-    "pino-pretty": "5.0.2"
+    "pino-pretty": "5.1.0",
+    "uuid": "^8.3.2"
   },
   "devDependencies": {
     "@redwoodjs/auth": "0.34.1",
     "@redwoodjs/dev-server": "0.34.1",
-    "@types/jsonwebtoken": "8.5.1",
+    "@types/graphql-depth-limit": "^1.1.2",
+    "@types/jsonwebtoken": "8.5.3",
     "@types/lodash.merge": "4.6.6",
     "@types/lodash.omitby": "4.6.6",
+    "@types/uuid": "^8.3.0",
     "split2": "3.2.2"
   },
   "jest": {

packages/api/src/functions/graphql.ts

@@ -1,7 +1,15 @@
-import type { Context, ContextFunction } from 'apollo-server-core'
+import type {
+  Context,
+  ContextFunction,
+  GraphQLRequestContext,
+} from 'apollo-server-core'
 import { ApolloServer } from 'apollo-server-lambda'
 import type { Config, CreateHandlerOptions } from 'apollo-server-lambda'
+import type { ApolloServerPlugin } from 'apollo-server-plugin-base'
 import type { APIGatewayProxyEvent, Context as LambdaContext } from 'aws-lambda'
+import depthLimit from 'graphql-depth-limit'
+import { BaseLogger } from 'pino'
+import { v4 as uuidv4 } from 'uuid'
 
 import type { AuthContextPayload } from 'src/auth'
 import { getAuthenticationContext } from 'src/auth'
@@ -18,6 +26,156 @@ export type GetCurrentUser = (
   req?: AuthContextPayload[2]
 ) => Promise<null | Record<string, unknown> | string>
 
+/**
+ * Settings for limiting the complexity of the queries solely by their depth.
+ * Use by graphql-depth-limit,
+ *
+ * @see https://github.com/stems/graphql-depth-limit
+ */
+type DepthLimitOptions = { maxDepth: number; ignore?: string[] }
+
+/**
+ * Options for request and response information to include in the log statements
+ * output by UseRedwoodLogger around the execution event
+ */
+type LoggerOptions = {
+  data?: boolean
+  operationName?: boolean
+  requestId?: boolean
+  query?: boolean
+  tracing?: boolean
+  userAgent?: boolean
+}
+
+/**
+ * Configure the logger.
+ *
+ * @param logger your logger
+ * @param options the LoggerOptions such as tracing, operationName, etc
+ */
+type LoggerConfig = { logger: BaseLogger; options?: LoggerOptions }
+
+/**
+ * This plugin logs every time an operation is being executed and
+ * when the execution of the operation is done.
+ *
+ * It adds information using a child logger from the context
+ * such as the operation name, request id, errors, and header info
+ * to help trace and diagnose issues.
+ *
+ * Tracing and timing information can be set in LoggerConfig options.
+ *
+ * @see https://www.apollographql.com/docs/apollo-server/integrations/plugins/
+ * @returns
+ */
+const UseRedwoodLogger = (loggerConfig?: LoggerConfig): ApolloServerPlugin => {
+  return {
+    requestDidStart(requestContext: GraphQLRequestContext) {
+      const logger = requestContext.logger as BaseLogger
+
+      const includeData = loggerConfig?.options?.data || true
+      const includeOperationName = loggerConfig?.options?.operationName || true
+      const includeRequestId = loggerConfig?.options?.requestId
+      const includeTracing = loggerConfig?.options?.tracing
+      const includeUserAgent = loggerConfig?.options?.userAgent
+      const includeQuery = loggerConfig?.options?.query
+
+      if (!logger) {
+        return
+      }
+
+      const childLoggerOptions = {} as any
+
+      if (includeUserAgent) {
+        childLoggerOptions['userAgent'] =
+          requestContext.request.http?.headers.get('user-agent') as string
+      }
+
+      if (includeQuery) {
+        childLoggerOptions['query'] = requestContext.request.query
+      }
+
+      const childLogger = logger.child({
+        name: 'apollo-graphql-server',
+        ...childLoggerOptions,
+      })
+
+      const options = {} as any
+
+      if (includeTracing) {
+        options['metrics'] = requestContext.metrics
+      }
+
+      childLogger.info({ ...options }, 'GraphQL requestDidStart')
+
+      return {
+        executionDidStart(requestContext: GraphQLRequestContext) {
+          const options = {} as any
+
+          if (includeOperationName) {
+            options['operationName'] = requestContext.operationName
+          }
+
+          if (includeRequestId) {
+            options['requestId'] =
+              requestContext.request.http?.headers.get('x-amz-request-id') ||
+              uuidv4()
+          }
+
+          childLogger.debug({ ...options }, 'GraphQL executionDidStart')
+        },
+        willSendResponse(requestContext: GraphQLRequestContext) {
+          const options = {} as any
+
+          if (includeData) {
+            options['data'] = requestContext.response?.data
+          }
+
+          if (includeOperationName && requestContext.operationName) {
+            options['operationName'] = requestContext.operationName
+          }
+
+          if (includeRequestId) {
+            options['requestId'] =
+              requestContext.request.http?.headers.get('x-amz-request-id') ||
+              uuidv4()
+          }
+
+          if (includeTracing) {
+            options['tracing'] = requestContext.response?.extensions?.tracing
+          }
+
+          childLogger.info({ ...options }, 'GraphQL willSendResponse')
+        },
+        didEncounterErrors(requestContext: GraphQLRequestContext) {
+          const options = {} as any
+
+          if (includeOperationName) {
+            options['operationName'] = requestContext.operationName
+          }
+
+          if (includeRequestId) {
+            options['requestId'] =
+              requestContext.request.http?.headers.get('x-amz-request-id') ||
+              uuidv4()
+          }
+
+          if (includeTracing) {
+            options['tracing'] = requestContext.response?.extensions?.tracing
+          }
+          childLogger.error(
+            {
+              errors: requestContext.errors,
+              ...options,
+            },
+            'GraphQL didEncounterErrors'
+          )
+        },
+      }
+    },
+  }
+}
+
 /**
  * We use Apollo Server's `context` option as an entry point to construct our
  * own global context.
@@ -71,18 +229,43 @@ interface GraphQLHandlerOptions extends Config {
    * Modify the resolver and global context.
    */
   context?: Context | ContextFunction
+
   /**
    * An async function that maps the auth token retrieved from the request headers to an object.
    * Is it executed when the `auth-provider` contains one of the supported providers.
    */
   getCurrentUser?: GetCurrentUser
+
   /**
    * A callback when an unhandled exception occurs. Use this to disconnect your prisma instance.
    */
   onException?: () => void
 
+  /**
+   * CORS configuration
+   */
   cors?: CreateHandlerOptions['cors']
+
+  /**
+   * Customize GraphQL Logger with options
+   */
+  loggerConfig?: LoggerConfig
+
+  /**
+   * Healthcheck
+   */
   onHealthCheck?: CreateHandlerOptions['onHealthCheck']
+
+  /**
+   * Limit the complexity of the queries solely by their depth.
+   * @see https://www.npmjs.com/package/graphql-depth-limit#documentation
+   */
+  depthLimitOptions?: DepthLimitOptions
+
+  /**
+   * Custom Apollo Server plugins
+   */
+  extraPlugins?: ApolloServerPlugin[]
 }
 /**
  * Creates an Apollo GraphQL Server.
@@ -96,15 +279,41 @@ export const createGraphQLHandler = ({
   getCurrentUser,
   onException,
   cors,
+  loggerConfig,
   onHealthCheck,
+  extraPlugins,
+  depthLimitOptions,
   ...options
 }: GraphQLHandlerOptions = {}) => {
   const isDevEnv = process.env.NODE_ENV === 'development'
+
+  const plugins = options.plugins || []
+
+  plugins.push(UseRedwoodLogger(loggerConfig))
+
+  if (extraPlugins && extraPlugins.length > 0) {
+    plugins.push(...extraPlugins)
+  }
+
+  // extract depth limit configuration and use a sensible default
+  const ignore = (depthLimitOptions && depthLimitOptions.ignore) || []
+  const maxDepth = (depthLimitOptions && depthLimitOptions.maxDepth) || 10
+
+  const validationRules = options.validationRules || []
+
+  validationRules.push(depthLimit(maxDepth, { ignore }))
+
   const handler = new ApolloServer({
     // Turn off playground, introspection and debug in production.
     debug: isDevEnv,
     introspection: isDevEnv,
+    logger: loggerConfig && loggerConfig.logger,
     playground: isDevEnv,
+    plugins,
+    // Log trace timings if set in loggerConfig
+    tracing: loggerConfig?.options?.tracing,
+    // Limits the depth of your GraphQL selection sets.
+    validationRules,
     // Log the errors in the console
     formatError: (error) => {
       if (isDevEnv) {

packages/core/package.json

@@ -34,8 +34,8 @@
     "babel-plugin-inline-react-svg": "2.0.1",
     "babel-plugin-module-resolver": "4.1.0",
     "core-js": "3.13.1",
-    "graphql": "15.5.0",
-    "graphql-tag": "2.12.4",
+    "graphql": "15.5.1",
+    "graphql-tag": "2.12.5",
     "glob": "7.1.7",
     "@babel/runtime-corejs3": "7.14.0",
     "x----x----x": "^0 Bins",

packages/create-redwood-app/template/api/src/functions/graphql.ts

@@ -6,9 +6,11 @@ import {
 
 import schemas from 'src/graphql/**/*.{js,ts}'
 import { db } from 'src/lib/db'
+import { logger } from 'src/lib/logger'
 import services from 'src/services/**/*.{js,ts}'
 
 export const handler = createGraphQLHandler({
+  loggerConfig: { logger, options: {} },
   schema: makeMergedSchema({
     schemas,
     services: makeServices({ services }),

packages/forms/src/FormError.tsx

@@ -56,7 +56,7 @@ const FormError = ({
     !!error.networkError && Object.keys(error.networkError).length > 0
 
   if (hasGraphQLError) {
-    const errors = error.graphQLErrors[0].extensions?.exception.messages
+    const errors = error.graphQLErrors[0].extensions?.exception?.messages
     rootMessage = error.graphQLErrors[0].message ?? 'Something went wrong.'
     for (const e in errors) {
       errors[e].forEach((fieldError: any) => {

packages/graphql-server/package.json

@@ -10,37 +10,39 @@
   "types": "./dist/index.d.ts",
   "license": "MIT",
   "dependencies": {
-    "@envelop/apollo-tracing": "0.1.0",
+    "@envelop/apollo-server-errors": "0.0.1",
     "@envelop/core": "0.3.1",
-    "@envelop/depth-limit": "0.1.0",
-    "@envelop/disable-introspection": "0.0.1",
+    "@envelop/depth-limit": "0.2.0",
+    "@envelop/disable-introspection": "0.1.0",
     "@envelop/filter-operation-type": "0.1.0",
-    "@envelop/parser-cache": "0.1.0",
-    "@envelop/validation-cache": "0.1.0",
+    "@envelop/parser-cache": "0.2.0",
+    "@envelop/validation-cache": "0.2.0",
     "@graphql-tools/merge": "6.2.14",
     "@graphql-tools/schema": "7.1.5",
     "@graphql-tools/utils": "7.10.0",
     "@prisma/client": "2.25.0",
     "@redwoodjs/api": "0.34.1",
     "@types/pino": "6.3.8",
     "core-js": "3.13.1",
+    "graphql": "15.5.1",
     "graphql-helix": "1.6.1",
     "graphql-playground-html": "1.6.29",
-    "graphql-scalars": "1.9.3",
-    "graphql": "15.5.0",
+    "graphql-scalars": "1.10.0",
     "jsonwebtoken": "8.5.1",
     "jwks-rsa": "1.8.1",
     "lodash.merge": "4.6.2",
     "lodash.omitby": "4.6.0",
-    "pino-pretty": "5.0.2",
-    "pino": "6.11.3"
+    "pino": "6.11.3",
+    "pino-pretty": "5.1.0",
+    "uuid": "^8.3.2"
   },
   "devDependencies": {
     "@redwoodjs/auth": "0.34.1",
     "@redwoodjs/dev-server": "0.34.1",
-    "@types/jsonwebtoken": "8.3.9",
+    "@types/jsonwebtoken": "8.5.3",
     "@types/lodash.merge": "4.6.6",
     "@types/lodash.omitby": "4.6.6",
+    "@types/uuid": "^8.3.0",
     "split2": "3.2.2"
   },
   "jest": {