Merge pull request #110 from MakerXStudio/support-subscription-operat…

…ion-logging-with-custom-log-level

Support subscription operation logging with custom log level

.vscode/settings.json

@@ -2,6 +2,7 @@
   "editor.formatOnSave": true,
   "editor.defaultFormatter": "esbenp.prettier-vscode",
   "editor.codeActionsOnSave": {
-    "source.fixAll.eslint": true
+    "source.fixAll.eslint": true,
+    "source.organizeImports": true
   }
-}
+}

README.md

@@ -119,26 +119,11 @@ const graphqlServer = createServer({
 
 ### logGraphQLOperation
 
-The `logGraphQLOperation` function will log:
+Logs a GraphQL operation in a consistent format with the option of including any additional data. Top level and result level log data with null or undefined values will be omitted for berevity.
 
-- `operationName`: the operation name, if supplied
-- `query`: the formatted graphql query or mutation, or 'IntrospectionQuery'
-- `variables`: the graphql request variables
-- `duration`: the duration of request processing
-- `errors`: the graphql response errors, if any
+Refer to the `GraphQLLogOperationInfo` type for the definition of input.
 
-Notes:
-
-- null or undefined values will be omitted
-- introspection queries will not be logged outside of production
-
-This function can be used across implementations, e.g. in a [GraphQL Envelop plugin](https://www.envelop.dev/docs/plugins) or [ApolloServer plugin](https://www.apollographql.com/docs/apollo-server/integrations/plugins/).
-
-### logGraphQLExecutionArgs
-
-The `logGraphQLExecutionArgs` will log `operationName`, `query` and `variables` params from the GraphQL `ExecutionArgs`.
-
-This can be used when logging from execution callbacks, e.g. graphql-ws Server [onOperation](https://the-guild.dev/graphql/ws/docs/interfaces/server.ServerOptions#onoperation) and [onNext](https://the-guild.dev/graphql/ws/docs/interfaces/server.ServerOptions#onnext).
+This function can be used across implementations, e.g. in a [GraphQL Envelop plugin](https://www.envelop.dev/docs/plugins) or [ApolloServer plugin](https://github.com/MakerXStudio/graphql-apollo-server/blob/main/src/plugins/graphql-operation-logging-plugin.ts).
 
 ## GraphQL subscriptions
 

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@makerx/graphql-core",
-  "version": "2.0.0",
+  "version": "2.1.0",
   "private": false,
   "description": "A set of core GraphQL utilities that MakerX uses to build GraphQL APIs",
   "author": "MakerX",

src/logging.ts

@@ -1,55 +1,136 @@
 import { isLocalDev, Logger } from '@makerx/node-common'
-import { ExecutionArgs, GraphQLFormattedError, print } from 'graphql'
+import { ExecutionArgs, GraphQLFormattedError, OperationTypeNode, print } from 'graphql'
+import { ExecutionResult } from 'graphql-ws'
 import omitBy from 'lodash.omitby'
-import { isIntrospectionQuery, isNil } from './utils'
 import { GraphQLContext } from './context'
+import { isIntrospectionQuery, isNil } from './utils'
 
-interface GraphQLLogOperationInfo {
-  started: number
+type LogFunction = Logger['info']
+export type LoggerLogFunctions<T extends Logger> = {
+  [Property in keyof T]: LogFunction
+}
+
+/**
+ * Info for logging a GraphQL operation in a consistent format with the option of including any additional data.
+ */
+export interface GraphQLLogOperationInfo<TLogger extends Logger = Logger> extends Record<string, unknown> {
+  /**
+   * The message to log, defaults to 'GraphQL operation'.
+   */
+  message?: string
+  /**
+   * The timestamp when the operation started, if supplied, the duration will be logged.
+   */
+  started?: number
+  /**
+   * The type of GraphQL operation.
+   */
+  type?: OperationTypeNode | null
+  /**
+   * The name of the GraphQL operation.
+   */
   operationName?: string | null
+  /**
+   * The formatted GraphQL query.
+   */
   query?: string | null
+  /**
+   * The GraphQL variables.
+   */
   variables?: Record<string, unknown> | null
-  result: {
+  /**
+   * The result of the GraphQL operation.
+   * Generally, we don't log the data or extensions, just errors.
+   */
+  result?: {
     data?: Record<string, unknown> | null
     errors?: readonly GraphQLFormattedError[] | null
+    extensions?: Record<string, unknown> | null
+    hasNext?: boolean
   }
-  logger: Logger
+  /**
+   * Whether the operation is an introspection query.
+   */
+  isIntrospectionQuery?: boolean
+  /**
+   * Whether the operation is part of an incremental response.
+   */
+  isIncrementalResponse?: boolean
+  /**
+   * Whether the operation is a subsequent payload of an incremental response.
+   */
+  isSubsequentPayload?: boolean
+  /**
+   * The logger to use.
+   */
+  logger: TLogger
+  /**
+   * The logger function to use, defaults to 'info'.
+   */
+  logLevel?: keyof LoggerLogFunctions<TLogger>
 }
 
-export const logGraphQLOperation = ({ started, operationName, query, variables, result: { errors }, logger }: GraphQLLogOperationInfo) => {
+/**
+ * Logs a GraphQL operation in a consistent format with the option of including any additional data.
+ * Top level and result entries with null or undefined values will be omitted.
+ */
+export const logGraphQLOperation = <TLogger extends Logger = Logger>({
+  message = 'GraphQL operation',
+  started,
+  type,
+  operationName,
+  query,
+  variables,
+  result,
+  logger,
+  logLevel = 'info',
+  ...rest
+}: GraphQLLogOperationInfo<TLogger>) => {
   const isIntrospection = query && isIntrospectionQuery(query)
   if (isLocalDev && isIntrospection) return
-  logger.info(
-    'GraphQL operation',
+  logger[logLevel as keyof Logger](
+    message,
     omitBy(
       {
+        type,
         operationName,
-        query: isIntrospection ? 'IntrospectionQuery' : query,
+        query,
         variables: variables && Object.keys(variables).length > 0 ? variables : undefined,
-        duration: Date.now() - started,
-        errors,
+        duration: started ? Date.now() - started : undefined,
+        result: result ? omitBy(result, isNil) : undefined,
+        isIntrospectionQuery: isIntrospection || undefined,
+        ...omitBy(rest, isNil),
       },
       isNil,
     ),
   )
 }
 
-/**
- * Logs `operationName`, `query` and `variables` params from the GraphQL `ExecutionArgs`.
- * If `args.contextValue` has a `logger` property, it will be used, otherwise the `logger` param will be used.
- */
-export const logGraphQLExecutionArgs = (args: ExecutionArgs, message: string, logger?: Logger) => {
+export const logSubscriptionOperation = <TLogger extends Logger = Logger>({
+  args,
+  result,
+  message,
+  logLevel,
+}: {
+  args: ExecutionArgs
+  result?: ExecutionResult
+  message?: string
+  logLevel?: keyof LoggerLogFunctions<TLogger>
+}) => {
+  const logger = (args.contextValue as GraphQLContext).logger as TLogger
+  if (!logger) return
+
   const { operationName, variableValues, document } = args
-  const contextLogger = (args.contextValue as Partial<GraphQLContext>).logger ?? logger
-  contextLogger?.info(
+  const { data, ...resultWithoutData } = result ?? {}
+
+  logGraphQLOperation({
     message,
-    omitBy(
-      {
-        operationName,
-        query: print(document),
-        variables: variableValues,
-      },
-      isNil,
-    ),
-  )
+    type: OperationTypeNode.SUBSCRIPTION,
+    operationName,
+    query: print(document),
+    variables: variableValues,
+    result: resultWithoutData,
+    logger,
+    logLevel,
+  })
 }

src/subscriptions/server.ts

@@ -1,20 +1,21 @@
 import { Logger } from '@makerx/node-common'
 import { GraphQLSchema } from 'graphql'
+import { CloseCode } from 'graphql-ws'
 import { useServer } from 'graphql-ws/lib/use/ws'
 import type { Server } from 'http'
 import pick from 'lodash.pick'
 import { WebSocketServer } from 'ws'
 import { JwtPayload } from '../context'
-import { logGraphQLExecutionArgs } from '../logging'
+import { logSubscriptionOperation } from '../logging'
 import { CreateSubscriptionContext } from './context'
 import { extractTokenFromConnectionParams, getHost } from './utils'
-import { CloseCode } from 'graphql-ws'
 
-export function useSubscriptionsServer({
+export function useSubscriptionsServer<TLogger extends Logger = Logger>({
   schema,
   httpServer,
   createSubscriptionContext,
   logger,
+  operationLogLevel = 'info',
   path = '/graphql',
   verifyToken,
   requireAuth,
@@ -23,7 +24,8 @@ export function useSubscriptionsServer({
   schema: GraphQLSchema
   httpServer: Server
   createSubscriptionContext: CreateSubscriptionContext
-  logger: Logger
+  logger: TLogger
+  operationLogLevel?: keyof TLogger
   path?: string
   verifyToken?: (host: string, token: string) => Promise<JwtPayload>
   requireAuth?: boolean
@@ -99,10 +101,10 @@ export function useSubscriptionsServer({
         })
       },
       onOperation(_ctx, _message, args) {
-        logGraphQLExecutionArgs(args, 'GraphQL subscription operation')
+        logSubscriptionOperation({ args, logLevel: operationLogLevel })
       },
-      onNext(_ctx, _message, args, _result) {
-        logGraphQLExecutionArgs(args, 'GraphQL subscription result')
+      onNext(_ctx, _message, args, { data, ...result }) {
+        logSubscriptionOperation({ args, logLevel: operationLogLevel, result })
       },
     },
     wsServer,