diff --git a/graphql/Query/pipelinesResolver.js b/graphql/Query/pipelinesResolver.js index df35ef0bc1b..0d229c0b9b1 100644 --- a/graphql/Query/pipelinesResolver.js +++ b/graphql/Query/pipelinesResolver.js @@ -19,6 +19,9 @@ import { getCDAPConfig } from 'server/cdap-config'; import { getGETRequestOptions, requestPromiseWrapper } from 'gql/resolvers-common'; import { orderBy } from 'natural-orderby'; import { ApolloError } from 'apollo-server'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql'); let cdapConfig; getCDAPConfig().then(function(value) { @@ -27,6 +30,9 @@ getCDAPConfig().then(function(value) { export async function queryTypePipelinesResolver(parent, args, context) { const namespace = args.namespace; + const queryId = context.queryId || 'Internal'; + log.info(`[Query:${queryId}] Parent pipelinesResolver fetching apps list for namespace: ${namespace}`); + const options = getGETRequestOptions(); const pipelineArtifacts = ['cdap-data-pipeline', 'cdap-data-streams', 'cdap-sql-pipeline']; @@ -57,5 +63,7 @@ export async function queryTypePipelinesResolver(parent, args, context) { }; const apps = await requestPromiseWrapper(options, context, null, errorModifiersFn); + const appCount = apps && apps.applications ? apps.applications.length : 0; + log.info(`[Query:${queryId}] Parent pipelinesResolver successfully fetched ${appCount} apps for namespace: ${namespace}`); return apps; } diff --git a/graphql/graphql.js b/graphql/graphql.js index 208240f7a69..dd014f49bff 100644 --- a/graphql/graphql.js +++ b/graphql/graphql.js @@ -38,11 +38,17 @@ const getApolloServer = (cdapConfig, logger = console) => typeDefs, resolvers, context: ({ req }) => { + const queryId = Math.random().toString(36).substring(2, 9); + log.info(`[Query:${queryId}] Incoming GraphQL request context initialization.`); + if (!req || !req.headers || !req.headers.authorization) { + log.info(`[Query:${queryId}] No Authorization header. Bypassing session token verification.`); return { + queryId, loaders: createLoaders(), }; } + const sToken = req.headers['session-token']; const auth = req.headers.authorization; let userIdValue, userIdProperty; @@ -51,11 +57,14 @@ const getApolloServer = (cdapConfig, logger = console) => userIdValue = req.headers[userIdProperty]; } + log.info(`[Query:${queryId}] Verifying session token for authenticated user context...`); if (!sToken || (sToken && !sessionToken.validateToken(sToken, cdapConfig, logger, auth))) { throw new Error('Invalid Sesion Token'); } + log.info(`[Query:${queryId}] Session token validated successfully.`); return { + queryId, auth, userIdProperty, userIdValue, diff --git a/graphql/helpers/BatchEndpoints/nextRuntime.js b/graphql/helpers/BatchEndpoints/nextRuntime.js index e43b4668ff6..43e8bd54b3d 100644 --- a/graphql/helpers/BatchEndpoints/nextRuntime.js +++ b/graphql/helpers/BatchEndpoints/nextRuntime.js @@ -18,6 +18,9 @@ import { constructUrl } from 'server/url-helper'; import { getCDAPConfig } from 'server/cdap-config'; import { ApolloError } from 'apollo-server'; import { getPOSTRequestOptions, requestPromiseWrapper } from 'gql/resolvers-common'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql'); let cdapConfig; getCDAPConfig().then(function(value) { @@ -30,6 +33,9 @@ export async function batchNextRuntime(req, auth, userIdProperty, userIdValue) { options.url = constructUrl(cdapConfig, `/v3/namespaces/${namespace}/nextruntime`); const body = req.slice(0, 25).map((reqObj) => reqObj.program); options.body = body; + + const names = body.map(p => p.appId).join(', '); + log.info(`[DataLoader:nextRuntime] Dispatching batch request for ${body.length} pipelines: [${names}]`); const errorModifiersFn = (error, statusCode) => { return new ApolloError(error, statusCode, { errorOrigin: "runs" }); }; diff --git a/graphql/helpers/BatchEndpoints/programRuns.js b/graphql/helpers/BatchEndpoints/programRuns.js index bc31bfe2bf4..0c37db51332 100644 --- a/graphql/helpers/BatchEndpoints/programRuns.js +++ b/graphql/helpers/BatchEndpoints/programRuns.js @@ -17,8 +17,10 @@ import { constructUrl } from 'server/url-helper'; import { getCDAPConfig } from 'server/cdap-config'; import { ApolloError } from 'apollo-server'; - import { getPOSTRequestOptions, requestPromiseWrapper } from 'gql/resolvers-common'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql'); let cdapConfig; getCDAPConfig().then(function(value) { @@ -29,7 +31,12 @@ export async function batchProgramRuns(req, auth, userIdProperty, userIdValue) { const namespace = req[0].namespace; const options = getPOSTRequestOptions(); options.url = constructUrl(cdapConfig, `/v3/namespaces/${namespace}/runs`); - options.body = req.slice(0, 25).map((reqObj) => reqObj.program); + const body = req.slice(0, 25).map((reqObj) => reqObj.program); + options.body = body; + + const names = body.map(p => p.appId).join(', '); + log.info(`[DataLoader:programRuns] Dispatching batch request for ${body.length} pipelines: [${names}]`); + const errorModifiersFn = (error, statusCode) => { return new ApolloError(error, statusCode, { errorOrigin: 'programRuns' }); } diff --git a/graphql/helpers/BatchEndpoints/totalRuns.js b/graphql/helpers/BatchEndpoints/totalRuns.js index be7c9044c04..4af20e1d0ba 100644 --- a/graphql/helpers/BatchEndpoints/totalRuns.js +++ b/graphql/helpers/BatchEndpoints/totalRuns.js @@ -19,6 +19,9 @@ import { getCDAPConfig } from 'server/cdap-config'; import { getPOSTRequestOptions, requestPromiseWrapper } from 'gql/resolvers-common'; import { ApolloError } from 'apollo-server'; import chunk from 'lodash/chunk'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql'); let cdapConfig; getCDAPConfig().then(function(value) { @@ -35,6 +38,9 @@ export async function batchTotalRuns(req, auth, userIdProperty, userIdValue) { } const body = req.slice(0, 25).map((reqObj) => reqObj.program); + const names = body.map(p => p.appId).join(', '); + log.info(`[DataLoader:totalRuns] Dispatching batch request for ${body.length} pipelines: [${names}]`); + const chunkedBody = chunk(body, 100); let runInfo = await Promise.all( diff --git a/graphql/resolvers-common.js b/graphql/resolvers-common.js index 5919d1976e6..c8965efd6c6 100644 --- a/graphql/resolvers-common.js +++ b/graphql/resolvers-common.js @@ -16,6 +16,9 @@ import request from 'request'; import { ApolloError } from 'apollo-server'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql-client'); export function getGETRequestOptions() { return { @@ -43,21 +46,33 @@ export function requestPromiseWrapper(options, { auth: token, userIdProperty, us options.headers[userIdProperty] = userIdValue; } + if (!options.timeout) { + options.timeout = 5 * 60 * 1000; // 5mins + } + + const requestId = Math.random().toString(36).substring(2, 9); + const startTime = Date.now(); + log.info(`[Req:${requestId}] Sending backend request: ${options.method} ${options.url}`); + return new Promise((resolve, reject) => { request(options, (err, response, body) => { - const statusCode = response.statusCode; + const duration = Date.now() - startTime; + if (err) { + log.error(`[Req:${requestId}] Backend request failed after ${duration}ms: ${options.method} ${options.url}. Error: ${err.message || err}`); let exception; if (typeof errorModifiersFn === 'function') { - exception = errorModifiersFn(err, statusCode ? statusCode.toString() : '500'); + exception = errorModifiersFn(err, '500'); } else { - exception = new ApolloError(err, statusCode ? statusCode.toString() : '500'); + exception = new ApolloError(err, '500'); } return reject(exception); } + const statusCode = response ? response.statusCode : 500; if (typeof statusCode === 'undefined' || statusCode != 200) { + log.error(`[Req:${requestId}] Backend request failed with status ${statusCode} after ${duration}ms: ${options.method} ${options.url}`); let error; if (typeof errorModifiersFn === 'function') { error = errorModifiersFn(body, statusCode.toString()); @@ -67,6 +82,8 @@ export function requestPromiseWrapper(options, { auth: token, userIdProperty, us return reject(error); } + log.info(`[Req:${requestId}] Backend request completed successfully in ${duration}ms with status ${statusCode}: ${options.method} ${options.url}`); + let resultBody = body; if (typeof bodyModifiersFn === 'function') { resultBody = bodyModifiersFn(body); diff --git a/graphql/types/PipelineRecord/nextRuntimeResolver.js b/graphql/types/PipelineRecord/nextRuntimeResolver.js index 686922b561a..287ab20764c 100644 --- a/graphql/types/PipelineRecord/nextRuntimeResolver.js +++ b/graphql/types/PipelineRecord/nextRuntimeResolver.js @@ -15,10 +15,14 @@ */ import { PIPELINE_PROGRAMS_MAP } from 'gql/types/PipelineRecord/common'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql'); export async function nextRuntimeResolvers(parent, args, context) { const namespace = context.namespace; const name = parent.name; + const queryId = context.queryId || 'Internal'; const pipelineType = parent.artifact.name || 'cdap-data-pipeline'; @@ -30,11 +34,15 @@ export async function nextRuntimeResolvers(parent, args, context) { programId: programId, }; + log.info(`[Query:${queryId}] Queueing nextRuntime load for pipeline: ${name}`); + const nextRuntimeInfo = await context.loaders.nextRuntime.load({ namespace, program, }); + log.info(`[Query:${queryId}] Resolved nextRuntime for pipeline: ${name}`); + if (!nextRuntimeInfo) { return; } diff --git a/graphql/types/PipelineRecord/pipelineRunsResolver.js b/graphql/types/PipelineRecord/pipelineRunsResolver.js index e20173b33bf..26ce8f90cdf 100644 --- a/graphql/types/PipelineRecord/pipelineRunsResolver.js +++ b/graphql/types/PipelineRecord/pipelineRunsResolver.js @@ -15,10 +15,14 @@ */ import { PIPELINE_PROGRAMS_MAP } from 'gql/types/PipelineRecord/common'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql'); export async function pipelineRunsResolver(parent, args, context) { const namespace = context.namespace; const name = parent.name; + const queryId = context.queryId || 'Internal'; const pipelineType = parent.artifact.name || 'cdap-data-pipeline'; @@ -30,11 +34,15 @@ export async function pipelineRunsResolver(parent, args, context) { programId: programId, }; + log.info(`[Query:${queryId}] Queueing programRuns load for pipeline: ${name}`); + const runInfo = await context.loaders.programRuns.load({ namespace, program, }); + log.info(`[Query:${queryId}] Resolved programRuns for pipeline: ${name}`); + if (!runInfo || (Array.isArray(runInfo) && runInfo.length === 0)) { return; } diff --git a/graphql/types/PipelineRecord/totalRunsResolver.js b/graphql/types/PipelineRecord/totalRunsResolver.js index b94c7d2f397..a81f968cc8e 100644 --- a/graphql/types/PipelineRecord/totalRunsResolver.js +++ b/graphql/types/PipelineRecord/totalRunsResolver.js @@ -15,10 +15,14 @@ */ import { PIPELINE_PROGRAMS_MAP } from 'gql/types/PipelineRecord/common'; +import log4js from 'log4js'; + +const log = log4js.getLogger('graphql'); export async function totalRunsResolvers(parent, args, context) { const namespace = context.namespace; const name = parent.name; + const queryId = context.queryId || 'Internal'; const pipelineType = parent.artifact.name || 'cdap-data-pipeline'; @@ -30,11 +34,15 @@ export async function totalRunsResolvers(parent, args, context) { programId: programId, }; + log.info(`[Query:${queryId}] Queueing totalRuns load for pipeline: ${name}`); + const runInfo = await context.loaders.totalRuns.load({ namespace, program, }); + log.info(`[Query:${queryId}] Resolved totalRuns for pipeline: ${name}`); + if (!runInfo || !runInfo.runCount) { return 0; }