From 332b0a08a6459f43bb3efa24de6720112445d5b3 Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Thu, 19 Oct 2023 17:25:43 +0800 Subject: [PATCH 1/5] support logging subscription operations with custom log level (e.g. audit) plus tweak logGraphQLOperation output --- .vscode/settings.json | 5 ++- README.md | 6 --- src/logging.ts | 82 ++++++++++++++++++++++++------------- src/subscriptions/server.ts | 16 ++++---- 4 files changed, 66 insertions(+), 43 deletions(-) diff --git a/.vscode/settings.json b/.vscode/settings.json index 508381a..34d2b3e 100644 --- a/.vscode/settings.json +++ b/.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 } -} \ No newline at end of file +} diff --git a/README.md b/README.md index 170e4f2..ef1d005 100644 --- a/README.md +++ b/README.md @@ -134,12 +134,6 @@ Notes: 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). - ## GraphQL subscriptions This library includes a `subscriptions` module to provide simple setup using the [GraphQL WS](https://the-guild.dev/graphql/ws) package. diff --git a/src/logging.ts b/src/logging.ts index 6957e04..f57d5d1 100644 --- a/src/logging.ts +++ b/src/logging.ts @@ -1,55 +1,81 @@ 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 +interface GraphQLLogOperationInfo { + message?: string + started?: number + type?: OperationTypeNode | null operationName?: string | null query?: string | null variables?: Record | null - result: { + result?: { data?: Record | null errors?: readonly GraphQLFormattedError[] | null + hasNext?: boolean } - logger: Logger + logger: TLogger + logLevel?: keyof TLogger } -export const logGraphQLOperation = ({ started, operationName, query, variables, result: { errors }, logger }: GraphQLLogOperationInfo) => { +export const logGraphQLOperation = ({ + message = 'GraphQL operation', + started, + type, + operationName, + query, + variables, + result, + logger, + logLevel = 'info', +}: GraphQLLogOperationInfo) => { 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, }, 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 = ({ + args, + result, + message, + logLevel, +}: { + args: ExecutionArgs + result?: ExecutionResult + message?: string + logLevel?: keyof TLogger +}) => { + const logger = (args.contextValue as GraphQLContext).logger as TLogger + if (!logger) return + const { operationName, variableValues, document } = args - const contextLogger = (args.contextValue as Partial).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, + }) } diff --git a/src/subscriptions/server.ts b/src/subscriptions/server.ts index 84a384d..368d292 100644 --- a/src/subscriptions/server.ts +++ b/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({ 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 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, From a0647f89327c165b3f04d246ec8386de57ef73b1 Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Thu, 19 Oct 2023 17:28:06 +0800 Subject: [PATCH 2/5] bump minor version --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index 0eefe44..7ee73c0 100644 --- a/package.json +++ b/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", From d3f3c7de14ed723e398671d965c3912722aa52fc Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Fri, 20 Oct 2023 09:50:34 +0800 Subject: [PATCH 3/5] Update logGraphQLOperation input type to accept additional data. Update doc to refer to the tsdoc of the input type. --- README.md | 15 +++---------- src/logging.ts | 58 ++++++++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 59 insertions(+), 14 deletions(-) diff --git a/README.md b/README.md index ef1d005..2ca168f 100644 --- a/README.md +++ b/README.md @@ -119,20 +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/). +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 diff --git a/src/logging.ts b/src/logging.ts index f57d5d1..4e44f9c 100644 --- a/src/logging.ts +++ b/src/logging.ts @@ -5,22 +5,74 @@ import omitBy from 'lodash.omitby' import { GraphQLContext } from './context' import { isIntrospectionQuery, isNil } from './utils' -interface GraphQLLogOperationInfo { +export type LoggerLogFunctions = { + [Property in keyof T]: (message: string, ...optionalParams: unknown[]) => void +} + +/** + * Info for logging a GraphQL operation in a consistent format with the option of including any additional data. + */ +export interface GraphQLLogOperationInfo extends Record { + /** + * 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 | null + /** + * The result of the GraphQL operation. + * Generally, we don't log the data or extensions, just errors. + */ result?: { data?: Record | null errors?: readonly GraphQLFormattedError[] | null + extensions?: Record | null hasNext?: boolean } + /** + * 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 - logLevel?: keyof TLogger + /** + * The logger function to use, defaults to 'info'. + */ + logLevel?: keyof LoggerLogFunctions } +/** + * 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 = ({ message = 'GraphQL operation', started, @@ -31,6 +83,7 @@ export const logGraphQLOperation = ({ result, logger, logLevel = 'info', + ...rest }: GraphQLLogOperationInfo) => { const isIntrospection = query && isIntrospectionQuery(query) if (isLocalDev && isIntrospection) return @@ -45,6 +98,7 @@ export const logGraphQLOperation = ({ duration: started ? Date.now() - started : undefined, result: result ? omitBy(result, isNil) : undefined, isIntrospectionQuery: isIntrospection || undefined, + ...omitBy(rest, isNil), }, isNil, ), From 098e8fa8f5e599595cd22b8c8b193b4f64661428 Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Fri, 20 Oct 2023 09:56:41 +0800 Subject: [PATCH 4/5] use better logLevel typing --- src/logging.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/logging.ts b/src/logging.ts index 4e44f9c..84976ed 100644 --- a/src/logging.ts +++ b/src/logging.ts @@ -114,7 +114,7 @@ export const logSubscriptionOperation = ({ args: ExecutionArgs result?: ExecutionResult message?: string - logLevel?: keyof TLogger + logLevel?: keyof LoggerLogFunctions }) => { const logger = (args.contextValue as GraphQLContext).logger as TLogger if (!logger) return From 97da08da5688627d1dd7f7aafc27fcb1bc04c211 Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Fri, 20 Oct 2023 09:58:25 +0800 Subject: [PATCH 5/5] Use log method typing from Logger --- src/logging.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/logging.ts b/src/logging.ts index 84976ed..6dd6afe 100644 --- a/src/logging.ts +++ b/src/logging.ts @@ -5,8 +5,9 @@ import omitBy from 'lodash.omitby' import { GraphQLContext } from './context' import { isIntrospectionQuery, isNil } from './utils' +type LogFunction = Logger['info'] export type LoggerLogFunctions = { - [Property in keyof T]: (message: string, ...optionalParams: unknown[]) => void + [Property in keyof T]: LogFunction } /**