diff --git a/packages/graphql-mesh/custom-plugins/fetch.ts b/packages/graphql-mesh/custom-plugins/fetch.ts deleted file mode 100644 index 038ed61..0000000 --- a/packages/graphql-mesh/custom-plugins/fetch.ts +++ /dev/null @@ -1,51 +0,0 @@ -import { type Plugin } from '@envelop/core'; - -import {Logger} from '../utils/logger' - - -export default () => { - return { - onFetch({ context, info }) { - - if (!info) { - return; - } -//rawSource.rawSource.handler.config.source -//info.parentType._fields.getFeatureToggles_v1.description -//info.variableValues - const start = Date.now(); - let rawSource=context[info.sourceName] - console.log("rawSource", rawSource) - let endpoint=rawSource.rawSource.handler.config.endpoint - let operation=info.operation.name - let description=info.parentType._fields[info.path.key].description - return (tt) => { - const duration = Date.now() - start; - let response=tt.response - let status=response.options.status - let url=response.options.url - //const timing = `${info.fieldName};desc="${info.fieldName} (${info.sourceName})";dur=${duration}`; - Logger.onFetch(context.request,info.fieldName,info.sourceName,info.path.key,endpoint,operation,info.variableValues,description,duration) - }; - }, - - onExecute() { - return { - onExecuteDone({ args }) { - // @ts-ignore - const { timings } = args.contextValue; - if (!timings) { - return; - } - - // @ts-ignore - args.contextValue.res.setHeader?.( - 'Server-Timing', - timings.join(', ') - ); - }, - }; - }, - - }; -}; diff --git a/packages/graphql-mesh/custom-plugins/monitor-envelop.ts b/packages/graphql-mesh/custom-plugins/monitor-envelop.ts index 1000976..5ce854e 100644 --- a/packages/graphql-mesh/custom-plugins/monitor-envelop.ts +++ b/packages/graphql-mesh/custom-plugins/monitor-envelop.ts @@ -6,8 +6,8 @@ import { GraphQLError } from 'graphql'; * monitor plugin in order to get event contextual log and add some security rules * useful to * - log the graphql Query event - * - add desabled introspection alidation rule - * - remove suggestion + * - add desabled introspection validation rule + * - remove suggestion message * - log the execute result summary with executes duration * - remove not allowed introspection in result */ @@ -31,11 +31,10 @@ export default ({ options }): Plugin => { const isMaskSuggestion = options?.maskSuggestion?.enabled || false const maskSuggestionMessage = options?.maskSuggestion?.message || "" return { - onParse({ params, context }) { - Logger.graphqlQuery(context['request']['headers'], context['params']) - /*return ({ result, context, replaceParseResult }) => { - Logger.info('LOG', 'onParse', 'result', result) - }*/ + onParse({ context }) { + if (options.logOnParse) { + Logger.graphqlQuery(context['request']['headers'], context['params']) + } }, onValidate: ({ addValidationRule, context }) => { @@ -80,13 +79,12 @@ export default ({ options }): Plugin => { return function onValidateEnd({ valid, result, setResult }) { if (isMaskSuggestion && !valid) { - setResult(result.map((error) => formatter(error, maskSuggestionMessage))); + setResult(result.map((error: GraphQLError) => formatter(error, maskSuggestionMessage))); } }; }, - onExecute({ args, extendContext }) { - + onExecute(/*{ args, extendContext }*/) { let timestampDebut = new Date().getTime() return { before() { @@ -95,14 +93,15 @@ export default ({ options }): Plugin => { }, onExecuteDone({ result, args }) { const timestampDone = new Date().getTime(); - // short cut to desabled introspection response in case of bad configuration rule if (!allowIntrospection && args.contextValue['params'].query.includes('__schema')) { result['data'] = {} result['errors'] = [{ message: "Fordidden" }] Logger.error('SECU', 'onExecute', 'Introspection query deteted not allowed', args.contextValue['params']) } - Logger.endExec(args.contextValue['request']['headers'], result, timestampDone - timestampDebut, resultLogInfoLevel) + if (options.loOnExecuteDone) { + Logger.endExec(args.contextValue['request']['headers'], result, timestampDone - timestampDebut, resultLogInfoLevel) + } } } } diff --git a/packages/graphql-mesh/custom-plugins/monitor-fetch.ts b/packages/graphql-mesh/custom-plugins/monitor-fetch.ts index 8518ac9..26d7437 100644 --- a/packages/graphql-mesh/custom-plugins/monitor-fetch.ts +++ b/packages/graphql-mesh/custom-plugins/monitor-fetch.ts @@ -2,7 +2,7 @@ import { type Plugin } from '@envelop/core'; import { Logger } from '../utils/logger' -/**@ +/** * monitor fetch source * use to : * - add log event for each fetch like, url, response status, duration @@ -11,9 +11,8 @@ import { Logger } from '../utils/logger' export default ({ options }) => { return { onFetch({ context, info }) { - if (!info) { - Logger.warn("noFeychInfo","onFetch","no info in on fetch") + Logger.warn("noFeychInfo", "onFetch", "no info in on fetch") return; } const start = Date.now(); @@ -21,63 +20,46 @@ export default ({ options }) => { let description = info.parentType._fields[info.path.key].description return (fetch: any) => { - const duration = Date.now() - start; - let fetchInfo = {} - let httpStatus=null - let url=null - if (options.fullFetchInfo) { - fetchInfo = { - fieldName: info.fieldName, - sourceName: info.sourceName, - pathKey: info.path.key, - operation: info.operation.name, - variables: info.variables, - endpoint: rawSource.rawSource.handler.config.endpoint, - description: description - } - } else { - fetchInfo = { - fieldName: info.fieldName, - pathKey: info.path.key, - operation: info.operation.name, - variables: info.variableValues, - endpoint: rawSource.rawSource.handler.config.endpoint, + if (options.logOnFetch) { + const duration = Date.now() - start; + let fetchInfo = {} + let httpStatus = null + let url = null + if (options.fullFetchInfo) { + fetchInfo = { + fieldName: info.fieldName, + sourceName: info.sourceName, + pathKey: info.path.key, + operation: info.operation.name, + variables: info.variables, + endpoint: rawSource.rawSource.handler.config.endpoint, + description: description + } + } else { + fetchInfo = { + fieldName: info.fieldName, + pathKey: info.path.key, + operation: info.operation.name, + variables: info.variableValues, + endpoint: rawSource.rawSource.handler.config.endpoint, + } } - } - //const fetchResponseInfo = {} - if (fetch.response) { + //const fetchResponseInfo = {} + if (fetch.response) { - httpStatus=fetch.response.status - url=fetch.response.url - const options = fetch.response.options - if (options) { - fetchInfo['options'] = { - requestId: options.headers['x-request-id'], - server: options.headers['server'] + httpStatus = fetch.response.status + url = fetch.response.url + const options = fetch.response.options + if (options) { + fetchInfo['options'] = { + requestId: options.headers['x-request-id'], + server: options.headers['server'] + } } } + Logger.onFetch(context.request, url, httpStatus, duration, fetchInfo) } - Logger.onFetch(context.request, url, httpStatus,duration,fetchInfo) - }; - }, - - onExecute() { - return { - onExecuteDone({ args }) { - // @ts-ignore - const { timings } = args.contextValue; - if (!timings) { - return; - } - - // @ts-ignore - args.contextValue.res.setHeader?.( - 'Server-Timing', - timings.join(', ') - ); - }, - }; - }, - - }; -}; + } + } + } +} diff --git a/packages/graphql-mesh/custom-plugins/monitor-yoga.ts b/packages/graphql-mesh/custom-plugins/monitor-yoga.ts index f0b9bae..3cc29b4 100644 --- a/packages/graphql-mesh/custom-plugins/monitor-yoga.ts +++ b/packages/graphql-mesh/custom-plugins/monitor-yoga.ts @@ -12,30 +12,33 @@ import { v4 as uuidv4 } from 'uuid' * - log response sumary event * - remove a eventualy not allowed instropection data in result */ + export function useYagaMonitoring({ options }): Plugin { const isMaskErrors = options?.maskError?.enabled || process.env['MASK_ERRORS'] || false - // filter in production anyway + // filter error in production anyway const isFilterError = options?.filterError?.enabled || process.env['FILTER_ERRORS'] == 'true' || process.env['IS_PROUCTION_ENV'] == 'true' || false - const errorMaskMessage = options?.maskError?.message ? options.maskError.message : "something goes wrong" const responseLogInfoLevel = options?.responseLogInfoLevel ? options.responseLogInfoLevel : "low" - const resultLogInfoLevel = options?.resultLogInfoLevel ? options.resultLogInfoLevel : "low" - - + const resultLogInfoLevel = options?.resultLogInfoLevel ? options.resultLogInfoLevel : "medium" return { onRequest({ request/*, fetchAPI, endResponse */ }) { - Logger.onRequest(request) + if (options.LogOnRequest) { + // log only graphql request, avoid log other request like metric requests + if (request.url.includes("/graphql")) { + Logger.onRequest(request) + } + } // add resuestTimestamp in headers const timestamp = new Date().getTime(); request.headers.append("requestTimestamp", String(timestamp)) - + // add x-request-id in header if not present - if (!request.headers.get('x-request-id')){ + if (!request.headers.get('x-request-id')) { request.headers.append("x-request-id", uuidv4()) } - + }, onRequestParse(args) { const beforeTimestamp = new Date().getTime(); @@ -43,15 +46,29 @@ export function useYagaMonitoring({ options }): Plugin { return { onRequestParseDone(nRequestParseDoneEventPayload) { const timestamp = new Date().getTime(); - Logger.onRequestParseDone(requestHeaders, nRequestParseDoneEventPayload.requestParserResult['query'], nRequestParseDoneEventPayload.requestParserResult['operationName'], nRequestParseDoneEventPayload.requestParserResult['variables'], timestamp - beforeTimestamp) + if (options.logOnRequestParseDone) { + Logger.onRequestParseDone(requestHeaders, nRequestParseDoneEventPayload.requestParserResult['query'], nRequestParseDoneEventPayload.requestParserResult['operationName'], nRequestParseDoneEventPayload.requestParserResult['variables'], timestamp - beforeTimestamp) + } if (nRequestParseDoneEventPayload.requestParserResult['query'].includes('__schema')) { - Logger.introspection("onRequestParseDone", requestHeaders,nRequestParseDoneEventPayload.requestParserResult['query']) + Logger.introspection("onRequestParseDone", requestHeaders, nRequestParseDoneEventPayload.requestParserResult['query']) } } } }, onResultProcess(args) { - Logger.onResultProcess(args.request, args.result, resultLogInfoLevel) + if (options.logOnResultProcess) { + // calculate duration from request timestamp + let requestTimestamp: number = 0 + if (args.request['headers']) { + const requestTimestampString = args.request['headers'].get('requesttimestamp') + if (requestTimestampString) { + requestTimestamp = parseInt(requestTimestampString) + } + } + const responseTimestamp = new Date().getTime(); + Logger.onResultProcess(args.request, args.result, requestTimestamp > 0 ? responseTimestamp - requestTimestamp : 0, resultLogInfoLevel) + } + // if we want to replace all message with a generic message if (isMaskErrors) { if (args.result['errors']) { let errors = args.result['errors'] @@ -60,12 +77,12 @@ export function useYagaMonitoring({ options }): Plugin { } } } else { + // if we want to filter error to only return the message, don't return extend information like stacktrace if (isFilterError) { if (args.result['errors']) { let errors = args.result['errors'] - for (let i = 0; i < errors.length; i++) { - errors[i]= new GraphQLError(filter(errors[i]['message'])) + errors[i] = new GraphQLError(filterErrorMessage(errors[i]['message'])) } } @@ -75,14 +92,25 @@ export function useYagaMonitoring({ options }): Plugin { }, onResponse({ request, response }) { - if (request.method != 'OPTION') { - Logger.onResponse(request, response, responseLogInfoLevel) + // dont log options http + if (request.method != 'OPTIONS') { + if (options.logOnResponse) { + // only log graphql request don't log metrics or other requests + if (request.url.includes("/graphql")) { + Logger.onResponse(request, response, responseLogInfoLevel) + } + } } } } } -function filter(message: string) { +/** filterErrorMessage + * use to filter error message : + * - remove disabled introspection + * todo: add other filter rules to remove non expecting message +*/ +function filterErrorMessage(message: string) { if (message.includes("introspection has been disabled")) { return "forbidden" } diff --git a/packages/graphql-mesh/utils/logger.ts b/packages/graphql-mesh/utils/logger.ts index 6c58559..c858b7b 100644 --- a/packages/graphql-mesh/utils/logger.ts +++ b/packages/graphql-mesh/utils/logger.ts @@ -1,6 +1,8 @@ /** * Logger : Class static - * + * use to log event with much useful context information and some useful data + * + * TODO : split into specifiques loggers and core logger */ import { v4 as uuidv4 } from 'uuid'; @@ -15,7 +17,7 @@ export class Logger { private static envLog: string = process.env["LogEnvFieldToAdd"] // use to add env extra field in json log ex "app=graphql,env.name=production,env.site=Paris" private static localDateCountry: string = process.env["LogLocalDateCountry"] || "fr-FR" private static logHeaders = defineLogHeaders(process.env["LogHeaders"] || "headers.host=host,headers.origin,headers.user-agent=user-agent,headers.content-length=content-length,headers.authorization=authorization") - private static logContextHeaders = defineLogHeaders(process.env["LogHeadersContext"] || "ctx.requestId=x-request-id") + private static logContextHeaders = defineLogHeaders(process.env["LogContextHeaders"] || "ctx.requestId=x-request-id") private static skipHealthCheck = process.env["skipHealthCheck"] ? process.env["skipHealthCheck"] == "true" : true private static healthCheckHeaderName = process.env["healthCheckHeazder"] || "x-internal" private static HealthCheckHeaderValue = process.env["healthCheckHeaderValue"] || "health-check" @@ -24,7 +26,7 @@ export class Logger { } /** - * Core logger with Human format or machine one line json string format + * Core logger with Human format or machine in one line json string format */ private static log(level: string, typeEv: string, message: string, headers = null, onlyContextHeader: boolean, info: any = null, err = null) { @@ -74,7 +76,7 @@ export class Logger { } } catch (e) { - log['error'] = "error whileg getting log event contextual info :"+e.message + log['error'] = "error whileg getting log event contextual info :" + e.message } console.log(JSON.stringify(log)) } else { @@ -103,6 +105,11 @@ export class Logger { Logger.log('DEBUG', typeEv, source + ":" + message, headers, true, info, e) } } + + + /** + * log the on parse event + */ public static onParse(headers: any) { try { if (this.isEventToLog(headers)) { @@ -113,47 +120,50 @@ export class Logger { } } - public static endExec(headers: any, result: any, duration: number, resultLogInfoLevel) { + + /** + * log the on end exec done event + */ + public static endExec(headers: any, result: any, duration: number, resultLogInfo: any) { try { if (this.isEventToLog(headers)) { const info = { - result: { - hasErrors: (result['errors'] != undefined), - hasData: (result['data'] != undefined), - resultSummayInfo: InfoResult(result, this.maxSkackLogSize, resultLogInfoLevel) - }, + result: InfoResult(result, this.maxSkackLogSize, resultLogInfo), duration: duration, } Logger.log('INFO', "endExecDone", "Request", headers, true, info) } } catch (e) { - Logger.error('LOGGER_ERROR', 'endExec logger', 'error during log generation', headers,null, e) - + Logger.error('LOGGER_ERROR', 'endExec logger', 'error during log generation', headers, null, e) } } - public static onResultProcess(request: any, result: any, resultLogInfo) { - const headers = request['headers'] + /** + * log the on result process event + */ + public static onResultProcess(request: any, result: any, duration: number,resultLogInfo: any) { + const headers = request['headers'] try { if (this.isEventToLog(headers)) { - const info = { - hasErrors: result['errors'] ? true : false, - hasData: result['data'] ? true : false, - responseInfo: InfoResult(result, this.maxSkackLogSize, resultLogInfo) + result: InfoResult(result, this.maxSkackLogSize, resultLogInfo), + duration: duration } - Logger.log('INFO', "onResultProcess", "Result", headers, true, info) } } catch (e) { - Logger.error('LOGGER_ERROR', 'onResponse logger', 'error during log generation', headers,null, e) + Logger.error('LOGGER_ERROR', 'onResponse logger', 'error during log generation', headers, null, e) } } - + + /** + * log the on request parse done event + */ public static onRequestParseDone(headers: any, query: any, operation: string, variables: any, duration: number) { if (this.isEventToLog(headers)) { + const info = { operation: operation, query: query, @@ -163,22 +173,20 @@ export class Logger { Logger.log('INFO', "requestParseDone", "requestParse", headers, true, info) } } - + /** + * log the on reponse event http respnse return + */ public static onResponse(request: any, response: any, logResponseLevellevel: string) { const headers = request['headers'] - try { - + try { if (this.isEventToLog(headers)) { - // calculate duration from request timestamp const requestTimestampString: string = headers.get('requesttimestamp') let requestTimestamp: number; if (requestTimestampString) { requestTimestamp = parseInt(requestTimestampString) } - const responseTimestamp = new Date().getTime(); - const info = { request: { url: request.url, @@ -195,7 +203,7 @@ export class Logger { info.response['bodyExtract'] = extractBody(response.bodyInit, this.bodyMaxLogSize) } - Logger.log('INFO', "onResponse", "response", headers, true, info) + Logger.log('INFO', "onResponse", responseSummary(response.bodyInit), headers, true, info) } } catch (e) { @@ -205,7 +213,6 @@ export class Logger { public static introspection(headers, info, query) { try { - const info = { query: query } @@ -218,8 +225,6 @@ export class Logger { public static denyIntrospection(headers, info, message,) { try { - - Logger.warn('DENY_INTROSPECTION', info, message, headers) } catch (e) { @@ -229,8 +234,6 @@ export class Logger { public static allowIntrospection(headers, info, message,) { try { - - Logger.warn('ALLOW_INTROSPECTION', info, message, headers) } catch (e) { @@ -238,18 +241,15 @@ export class Logger { } } public static onRequest(request: any) { - const headers = request['headers'] + const headers = request['headers'] try { const headers = request['headers'] if (this.isEventToLog(headers)) { - const info = { - url: request.url, method: request.method, //body: request.body } - Logger.log('INFO', "onRequest", "request incomming", headers, false, info) } } @@ -258,7 +258,7 @@ export class Logger { } } - public static onFetch(request: any, url: string, httpStatus: string, duration: number,fetchInfo: any) { + public static onFetch(request: any, url: string, httpStatus: string, duration: number, fetchInfo: any) { try { const headers = request['headers'] const info = { @@ -285,7 +285,7 @@ export class Logger { Logger.log('INFO', "graphqlQuery", "GraphQL Query", headers, true, queryTolog) } } catch (e) { - Logger.error('LOGGER_ERROR', 'graphql query logger', 'error during log generation', headers,null, e) + Logger.error('LOGGER_ERROR', 'graphql query logger', 'error during log generation', headers, null, e) } } private static isEventToLog(headers): boolean { @@ -302,7 +302,6 @@ export class Logger { const headerMap = headers["_map"] if (headerMap) { if (this.logContextHeaders) { - for (const contextKey in this.logContextHeaders) { const contextHeader = this.logContextHeaders[contextKey] if (headerMap.get(contextHeader.header)) { @@ -317,22 +316,20 @@ export class Logger { } } } catch (e) { - Logger.error('LOGGER_ERROR', 'onheadersToLog', 'error during headers log generation', headers,null, e) + Logger.error('LOGGER_ERROR', 'onheadersToLog', 'error during headers log generation', headers, null, e) } return log } private static addHeadersToLog(log: any, headers: any) { - const headerMap = headers["_map"] + const headerMap = headers["_map"] try { - if (headerMap) { if (this.logHeaders) { for (const logHeaderKey in this.logHeaders) { const logHeader = this.logHeaders[logHeaderKey] if (headerMap.get(logHeader.header)) { - if (logHeader.header.toLowerCase() == "authorization") { addLog(log, logHeader.name, mask(headerMap.get('authorization'))) } else { @@ -357,22 +354,25 @@ function mask(stringToMask: string) { } function InfoResult(result: any, maxStackLogSize: number, resultLogInfoLevel: string) { - let responseInfo = {} + let resultInfo = {} let keys = null let nbKeys = 0 - let maxKeys = 20 + const maxKeys = 1 + const nbErrorsMaxToLog=3 if (result['errors']) { - responseInfo['errors'] = [] - responseInfo['nbErrors'] = result['errors'].length - + resultInfo['nbErrors'] = result['errors'].length if (resultLogInfoLevel != 'low') { + let nbErrors=0 + resultInfo['errors'] = [] for (const errorKey in result['errors']) { const error = result['errors'][errorKey] let logError = {} if (error['message']) { + if (nbErrorsMaxToLog > nbErrors ){ logError['message'] = error['message'] + } } - if (resultLogInfoLevel == 'higth') { + if (resultLogInfoLevel == 'hight') { if (error['path']) { logError['path'] = error['path'] } @@ -384,14 +384,13 @@ function InfoResult(result: any, maxStackLogSize: number, resultLogInfoLevel: st logError['extensions'] = error['extensions'] } } - responseInfo['errors'].push(logError) + resultInfo['errors'].push(logError) } } } else { - responseInfo['nbErrors'] = 0 + resultInfo['nbErrors'] = 0 } if (result['data']) { - if (resultLogInfoLevel != 'low') { let keys = null for (const key in result['data']) { if (result['data'].hasOwnProperty(key)) { @@ -405,11 +404,9 @@ function InfoResult(result: any, maxStackLogSize: number, resultLogInfoLevel: st nbKeys = nbKeys + 1 } } - responseInfo['dataFields'] = keys - responseInfo['nbDataField'] = nbKeys - } + resultInfo['dataFields'] = keys } - return responseInfo + return resultInfo } function extractBody(body: String, bodyMaxLogSize: number) { if (body != null) { @@ -418,6 +415,14 @@ function extractBody(body: String, bodyMaxLogSize: number) { return "" } } +function responseSummary(body: String) { + if (body != null) { + return "response :" + body.substring(0, 100) + " ... " + } else { + return "response : empty" + } +} + /** * Use to add some environment fields to log, like env.name, app.name ...