From 037bb98607423c1d7fb9199ef3a7912472bc8220 Mon Sep 17 00:00:00 2001 From: Nathaniel McAuliffe Date: Tue, 9 Nov 2021 11:24:17 -0500 Subject: [PATCH 1/5] fix(logging): Add context to webhook logs --- .../lambdas/webhook/src/webhook/handler.ts | 60 ++++++++++++++----- .../lambdas/webhook/src/webhook/logger.ts | 4 ++ 2 files changed, 50 insertions(+), 14 deletions(-) diff --git a/modules/webhook/lambdas/webhook/src/webhook/handler.ts b/modules/webhook/lambdas/webhook/src/webhook/handler.ts index 8d6c793d60..3ad5aa00c2 100644 --- a/modules/webhook/lambdas/webhook/src/webhook/handler.ts +++ b/modules/webhook/lambdas/webhook/src/webhook/handler.ts @@ -3,9 +3,10 @@ import { Webhooks } from '@octokit/webhooks'; import { sendActionRequest } from '../sqs'; import { CheckRunEvent, WorkflowJobEvent } from '@octokit/webhooks-types'; import { getParameterValue } from '../ssm'; -import { logger as rootLogger } from './logger'; +import { logger as rootLogger, LogFields } from './logger'; import { Response } from '../lambda'; +const supportedEvents = ['check_run', 'workflow_job']; const logger = rootLogger.getChildLogger(); export async function handle(headers: IncomingHttpHeaders, body: string): Promise { @@ -24,25 +25,49 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis return response; } const payload = JSON.parse(body); - logger.info(`Received Github event ${githubEvent} from ${payload.repository.full_name}`); + LogFields.fields.event = githubEvent; + LogFields.fields.repository = payload.repository.full_name; + LogFields.fields.action = payload.action; + + if (!supportedEvents.includes(githubEvent)) { + logger.error(LogFields.fields, `Unsupported event type.`); + return { + statusCode: 202, + body: `Ignoring unsupported event ${githubEvent}`, + }; + } + + LogFields.fields.name = payload[githubEvent].name; + LogFields.fields.status = payload[githubEvent].status; + + if (payload[githubEvent].started_at) { + LogFields.fields.started_at = payload[githubEvent].started_at; + } + + /* + The app subscribes to all `check_run` and `workflow_job` events. + If the event status is `completed`, log the data for workflow metrics. + */ + if (payload[githubEvent].completed_at) { + LogFields.fields.completed_at = payload[githubEvent].completed_at; + } + if (payload[githubEvent].conclusion) { + LogFields.fields.conclusion = payload[githubEvent].conclusion; + } if (isRepoNotAllowed(payload.repository.full_name)) { - console.warn(`Received event from unauthorized repository ${payload.repository.full_name}`); + logger.error(LogFields.fields, `Received event from unauthorized repository ${payload.repository.full_name}`); return { statusCode: 403, }; } + logger.info(LogFields.fields, `Received Github event`); + if (githubEvent == 'workflow_job') { response = await handleWorkflowJob(payload as WorkflowJobEvent, githubEvent); } else if (githubEvent == 'check_run') { response = await handleCheckRun(payload as CheckRunEvent, githubEvent); - } else { - logger.warn(`Ignoring unsupported event ${githubEvent}`); - response = { - statusCode: 202, - body: `Ignoring unsupported event ${githubEvent}`, - }; } return response; @@ -50,7 +75,10 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis async function verifySignature(githubEvent: string, signature: string, body: string): Promise { if (!signature) { - logger.error("Github event doesn't have signature. This webhook requires a secret to be configured."); + logger.error( + LogFields.fields, + "Github event doesn't have signature. This webhook requires a secret to be configured.", + ); return 500; } @@ -60,7 +88,7 @@ async function verifySignature(githubEvent: string, signature: string, body: str secret: secret, }); if (!(await webhooks.verify(body, signature))) { - logger.error('Unable to verify signature!'); + logger.error(LogFields.fields, 'Unable to verify signature!'); return 401; } return 200; @@ -70,7 +98,10 @@ async function handleWorkflowJob(body: WorkflowJobEvent, githubEvent: string): P const disableCheckWorkflowJobLabelsEnv = process.env.DISABLE_CHECK_WORKFLOW_JOB_LABELS || 'false'; const disableCheckWorkflowJobLabels = JSON.parse(disableCheckWorkflowJobLabelsEnv) as boolean; if (!disableCheckWorkflowJobLabels && !canRunJob(body)) { - logger.warn(`Received event contains runner labels '${body.workflow_job.labels}' that are not accepted.`); + logger.warn( + LogFields.fields, + `Received event contains runner labels '${body.workflow_job.labels}' that are not accepted.`, + ); return { statusCode: 202, body: `Received event contains runner labels '${body.workflow_job.labels}' that are not accepted.`, @@ -90,7 +121,7 @@ async function handleWorkflowJob(body: WorkflowJobEvent, githubEvent: string): P installationId: installationId, }); } - console.info(`Successfully queued job for ${body.repository.full_name}`); + logger.info(LogFields.fields, `Successfully queued job for ${body.repository.full_name}`); return { statusCode: 201 }; } @@ -108,7 +139,7 @@ async function handleCheckRun(body: CheckRunEvent, githubEvent: string): Promise installationId: installationId, }); } - console.info(`Successfully queued job for ${body.repository.full_name}`); + logger.info(LogFields.fields, `Successfully queued job for ${body.repository.full_name}`); return { statusCode: 201 }; } @@ -136,6 +167,7 @@ function canRunJob(job: WorkflowJobEvent): boolean { const runnerMatch = customWorkflowJobLabels.every((l) => runnerLabels.has(l)); logger.debug( + LogFields.fields, `Received workflow job event with labels: '${JSON.stringify(job.workflow_job.labels)}'. The event does ${ runnerMatch ? '' : 'NOT ' }match the configured labels: '${Array.from(runnerLabels).join(',')}'`, diff --git a/modules/webhook/lambdas/webhook/src/webhook/logger.ts b/modules/webhook/lambdas/webhook/src/webhook/logger.ts index b77bddf597..6cda29e921 100644 --- a/modules/webhook/lambdas/webhook/src/webhook/logger.ts +++ b/modules/webhook/lambdas/webhook/src/webhook/logger.ts @@ -8,3 +8,7 @@ export const logger = new Logger({ overwriteConsole: true, type: process.env.LOG_TYPE || 'pretty', }); + +export class LogFields { + static fields: { [key: string]: string } = {}; +} From 832204f04a86419fc22f45acac16380009805f20 Mon Sep 17 00:00:00 2001 From: Nathaniel McAuliffe Date: Wed, 10 Nov 2021 08:20:00 -0500 Subject: [PATCH 2/5] Update modules/webhook/lambdas/webhook/src/webhook/handler.ts Co-authored-by: Niek Palm --- modules/webhook/lambdas/webhook/src/webhook/handler.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/modules/webhook/lambdas/webhook/src/webhook/handler.ts b/modules/webhook/lambdas/webhook/src/webhook/handler.ts index 3ad5aa00c2..f96fbf6daf 100644 --- a/modules/webhook/lambdas/webhook/src/webhook/handler.ts +++ b/modules/webhook/lambdas/webhook/src/webhook/handler.ts @@ -62,7 +62,7 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis }; } - logger.info(LogFields.fields, `Received Github event`); + logger.info(LogFields.fields, `Processing Github event`); if (githubEvent == 'workflow_job') { response = await handleWorkflowJob(payload as WorkflowJobEvent, githubEvent); From 155d54d97a971100393ca226c0b988c3e4303f70 Mon Sep 17 00:00:00 2001 From: Nathaniel McAuliffe Date: Wed, 10 Nov 2021 08:23:38 -0500 Subject: [PATCH 3/5] Updating per recommendation --- .../webhook/lambdas/webhook/src/webhook/handler.ts | 13 +++---------- 1 file changed, 3 insertions(+), 10 deletions(-) diff --git a/modules/webhook/lambdas/webhook/src/webhook/handler.ts b/modules/webhook/lambdas/webhook/src/webhook/handler.ts index 3ad5aa00c2..850257e0a0 100644 --- a/modules/webhook/lambdas/webhook/src/webhook/handler.ts +++ b/modules/webhook/lambdas/webhook/src/webhook/handler.ts @@ -39,21 +39,14 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis LogFields.fields.name = payload[githubEvent].name; LogFields.fields.status = payload[githubEvent].status; - - if (payload[githubEvent].started_at) { - LogFields.fields.started_at = payload[githubEvent].started_at; - } + LogFields.fields.started_at = payload[githubEvent]?.started_at; /* The app subscribes to all `check_run` and `workflow_job` events. If the event status is `completed`, log the data for workflow metrics. */ - if (payload[githubEvent].completed_at) { - LogFields.fields.completed_at = payload[githubEvent].completed_at; - } - if (payload[githubEvent].conclusion) { - LogFields.fields.conclusion = payload[githubEvent].conclusion; - } + LogFields.fields.completed_at = payload[githubEvent]?.completed_at; + LogFields.fields.conclusion = payload[githubEvent]?.conclusion; if (isRepoNotAllowed(payload.repository.full_name)) { logger.error(LogFields.fields, `Received event from unauthorized repository ${payload.repository.full_name}`); From ddf55d1453317e41bf8bef906639118bf9b7d49f Mon Sep 17 00:00:00 2001 From: Nathaniel McAuliffe Date: Wed, 10 Nov 2021 08:24:21 -0500 Subject: [PATCH 4/5] Updating per recommendation --- modules/webhook/lambdas/webhook/src/webhook/handler.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/modules/webhook/lambdas/webhook/src/webhook/handler.ts b/modules/webhook/lambdas/webhook/src/webhook/handler.ts index 20d7572709..215018ac56 100644 --- a/modules/webhook/lambdas/webhook/src/webhook/handler.ts +++ b/modules/webhook/lambdas/webhook/src/webhook/handler.ts @@ -30,7 +30,7 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis LogFields.fields.action = payload.action; if (!supportedEvents.includes(githubEvent)) { - logger.error(LogFields.fields, `Unsupported event type.`); + logger.warn(LogFields.fields, `Unsupported event type.`); return { statusCode: 202, body: `Ignoring unsupported event ${githubEvent}`, From 6c8c28182a787b7e36ecb8e5fc81727942a5b4fb Mon Sep 17 00:00:00 2001 From: Nathaniel McAuliffe Date: Thu, 18 Nov 2021 10:32:35 -0500 Subject: [PATCH 5/5] Moving log fields to end, adjusting format --- .../lambdas/webhook/src/webhook/handler.ts | 18 +++++++++--------- .../lambdas/webhook/src/webhook/logger.ts | 4 ++++ 2 files changed, 13 insertions(+), 9 deletions(-) diff --git a/modules/webhook/lambdas/webhook/src/webhook/handler.ts b/modules/webhook/lambdas/webhook/src/webhook/handler.ts index 215018ac56..11b9b1ec76 100644 --- a/modules/webhook/lambdas/webhook/src/webhook/handler.ts +++ b/modules/webhook/lambdas/webhook/src/webhook/handler.ts @@ -30,7 +30,7 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis LogFields.fields.action = payload.action; if (!supportedEvents.includes(githubEvent)) { - logger.warn(LogFields.fields, `Unsupported event type.`); + logger.warn(`Unsupported event type.`, LogFields.print()); return { statusCode: 202, body: `Ignoring unsupported event ${githubEvent}`, @@ -49,13 +49,13 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis LogFields.fields.conclusion = payload[githubEvent]?.conclusion; if (isRepoNotAllowed(payload.repository.full_name)) { - logger.error(LogFields.fields, `Received event from unauthorized repository ${payload.repository.full_name}`); + logger.error(`Received event from unauthorized repository ${payload.repository.full_name}`, LogFields.print()); return { statusCode: 403, }; } - logger.info(LogFields.fields, `Processing Github event`); + logger.info(`Processing Github event`, LogFields.print()); if (githubEvent == 'workflow_job') { response = await handleWorkflowJob(payload as WorkflowJobEvent, githubEvent); @@ -69,8 +69,8 @@ export async function handle(headers: IncomingHttpHeaders, body: string): Promis async function verifySignature(githubEvent: string, signature: string, body: string): Promise { if (!signature) { logger.error( - LogFields.fields, "Github event doesn't have signature. This webhook requires a secret to be configured.", + LogFields.print(), ); return 500; } @@ -81,7 +81,7 @@ async function verifySignature(githubEvent: string, signature: string, body: str secret: secret, }); if (!(await webhooks.verify(body, signature))) { - logger.error(LogFields.fields, 'Unable to verify signature!'); + logger.error('Unable to verify signature!', LogFields.print()); return 401; } return 200; @@ -92,8 +92,8 @@ async function handleWorkflowJob(body: WorkflowJobEvent, githubEvent: string): P const disableCheckWorkflowJobLabels = JSON.parse(disableCheckWorkflowJobLabelsEnv) as boolean; if (!disableCheckWorkflowJobLabels && !canRunJob(body)) { logger.warn( - LogFields.fields, `Received event contains runner labels '${body.workflow_job.labels}' that are not accepted.`, + LogFields.print(), ); return { statusCode: 202, @@ -114,7 +114,7 @@ async function handleWorkflowJob(body: WorkflowJobEvent, githubEvent: string): P installationId: installationId, }); } - logger.info(LogFields.fields, `Successfully queued job for ${body.repository.full_name}`); + logger.info(`Successfully queued job for ${body.repository.full_name}`, LogFields.print()); return { statusCode: 201 }; } @@ -132,7 +132,7 @@ async function handleCheckRun(body: CheckRunEvent, githubEvent: string): Promise installationId: installationId, }); } - logger.info(LogFields.fields, `Successfully queued job for ${body.repository.full_name}`); + logger.info(`Successfully queued job for ${body.repository.full_name}`, LogFields.print()); return { statusCode: 201 }; } @@ -160,10 +160,10 @@ function canRunJob(job: WorkflowJobEvent): boolean { const runnerMatch = customWorkflowJobLabels.every((l) => runnerLabels.has(l)); logger.debug( - LogFields.fields, `Received workflow job event with labels: '${JSON.stringify(job.workflow_job.labels)}'. The event does ${ runnerMatch ? '' : 'NOT ' }match the configured labels: '${Array.from(runnerLabels).join(',')}'`, + LogFields.print(), ); return runnerMatch; } diff --git a/modules/webhook/lambdas/webhook/src/webhook/logger.ts b/modules/webhook/lambdas/webhook/src/webhook/logger.ts index 6cda29e921..9727c3b253 100644 --- a/modules/webhook/lambdas/webhook/src/webhook/logger.ts +++ b/modules/webhook/lambdas/webhook/src/webhook/logger.ts @@ -11,4 +11,8 @@ export const logger = new Logger({ export class LogFields { static fields: { [key: string]: string } = {}; + + public static print(): string { + return JSON.stringify(LogFields.fields); + } }