From b9d916e447b4cee87ceca97ce4f52de2cc3765da Mon Sep 17 00:00:00 2001 From: Boris Gvozdev Date: Wed, 6 Sep 2023 22:26:21 +1000 Subject: [PATCH 1/4] NONE: add profiling around calls to crypto lib --- src/config/metric-names.ts | 10 +++++-- src/main.ts | 4 +-- .../github/webhook/webhook-receiver-post.ts | 9 +++++++ src/util/encryption.ts | 27 +++++++++++++++---- src/worker/startup.ts | 4 +-- 5 files changed, 43 insertions(+), 11 deletions(-) diff --git a/src/config/metric-names.ts b/src/config/metric-names.ts index 40b8b33828..841cda8db1 100644 --- a/src/config/metric-names.ts +++ b/src/config/metric-names.ts @@ -82,7 +82,13 @@ export const metricPrReviewers = { failedCount: `${server}.prs.failed.count` }; -export const metricLag = { - lagHist: `${server}.lag.histogram` +export const metricPerf = { + lagHist: `${server}.lag.histogram`, + webhookShaGeneratorHist: `${server}.webhook.sha.generator.histogram`, + webhookShaGeneratorCnt: `${server}.webhook.sha.generator.count`, + hashWithSharedSecretHist: `${server}.hash.with.shared.secret.histogram`, + hashWithSharedSecretCnt: `${server}.hash.with.shared.secret.count`, + hashWithoutSharedSecretHist: `${server}.hash.without.shared.secret.histogram`, + hashWithoutSharedSecretCnt: `${server}.hash.without.shared.secret.count` }; diff --git a/src/main.ts b/src/main.ts index 0fda8f4817..91d141fef6 100644 --- a/src/main.ts +++ b/src/main.ts @@ -7,7 +7,7 @@ import { isNodeProd } from "utils/is-node-env"; import { getFrontendApp } from "./app"; import createLag from "event-loop-lag"; import { statsd } from "config/statsd"; -import { metricLag } from "config/metric-names"; +import { metricPerf } from "config/metric-names"; const start = async () => { initializeSentry(); @@ -18,7 +18,7 @@ const start = async () => { }); const lag = createLag(1000); setInterval(() => { - statsd.histogram(metricLag.lagHist, lag(), { }, { }); + statsd.histogram(metricPerf.lagHist, lag(), { }, { }); }, 1000); }; diff --git a/src/routes/github/webhook/webhook-receiver-post.ts b/src/routes/github/webhook/webhook-receiver-post.ts index 4851bd65af..f5b48df22d 100644 --- a/src/routes/github/webhook/webhook-receiver-post.ts +++ b/src/routes/github/webhook/webhook-receiver-post.ts @@ -23,6 +23,8 @@ import { dependabotAlertWebhookHandler } from "~/src/github/dependabot-alert"; import { extraLoggerInfo } from "./webhook-logging-extra"; import { secretScanningAlertWebhookHandler } from "~/src/github/secret-scanning-alert"; import { installationWebhookHandler } from "~/src/github/installation"; +import { statsd } from "config/statsd"; +import { metricPerf } from "config/metric-names"; export const WebhookReceiverPost = async (request: Request, response: Response): Promise => { const eventName = request.headers["x-github-event"] as string; @@ -42,7 +44,14 @@ export const WebhookReceiverPost = async (request: Request, response: Response): try { const { webhookSecrets, gitHubServerApp } = await getWebhookSecrets(uuid); const isVerified = webhookSecrets.some((secret, index) => { + + const started = new Date().getTime(); const matchesSignature = createHash(request.rawBody, secret) === signatureSHA256; + const finished = new Date().getTime(); + + statsd.histogram(metricPerf.webhookShaGeneratorHist, finished-started, { } ,{ }); + statsd.increment(metricPerf.webhookShaGeneratorCnt, { }, { }); + /** * The latest updated webhook secret will be at index 0, * Once we stop receiving logs with index other than 0, diff --git a/src/util/encryption.ts b/src/util/encryption.ts index 3f9a5bfb04..6d7a0fc36d 100644 --- a/src/util/encryption.ts +++ b/src/util/encryption.ts @@ -1,21 +1,38 @@ import { createHmac, createHash } from "crypto"; import { envVars } from "../config/env"; +import { metricPerf } from "config/metric-names"; +import { statsd } from "config/statsd"; export const createHashWithSharedSecret = (data?: string): string => { if (!data) { return ""; } - const cleanedData = removeNonAlphaNumericCharacters(data); - return createHmac("sha256", envVars.GLOBAL_HASH_SECRET) - .update(cleanedData) - .digest("hex"); + + const started = new Date().getTime(); + try { + const cleanedData = removeNonAlphaNumericCharacters(data); + return createHmac("sha256", envVars.GLOBAL_HASH_SECRET) + .update(cleanedData) + .digest("hex"); + } finally { + const finished = new Date().getTime(); + statsd.histogram(metricPerf.hashWithSharedSecretHist, finished-started, { } ,{ }); + statsd.increment(metricPerf.hashWithSharedSecretCnt, { }, { }); + } }; export const createHashWithoutSharedSecret = (data: string | null | undefined) => { if (!data) { return ""; } - return createHash("sha256").update(data).digest("hex"); + const started = new Date().getTime(); + try { + return createHash("sha256").update(data).digest("hex"); + } finally { + const finished = new Date().getTime(); + statsd.histogram(metricPerf.hashWithoutSharedSecretHist, finished-started, { } ,{ }); + statsd.increment(metricPerf.hashWithoutSharedSecretCnt, { }, { }); + } }; diff --git a/src/worker/startup.ts b/src/worker/startup.ts index c171c95756..e355d72ba6 100644 --- a/src/worker/startup.ts +++ b/src/worker/startup.ts @@ -1,7 +1,7 @@ import { sqsQueues } from "../sqs/queues"; import { getLogger } from "config/logger"; import { statsd } from "config/statsd"; -import { metricLag } from "config/metric-names"; +import { metricPerf } from "config/metric-names"; import createLag from "event-loop-lag"; const logger = getLogger("worker"); @@ -15,7 +15,7 @@ export const start = async () => { } const lag = createLag(1000); setInterval(() => { - statsd.histogram(metricLag.lagHist, lag(), { }, { }); + statsd.histogram(metricPerf.lagHist, lag(), { }, { }); }, 1000); logger.info("Micros Lifecycle: Starting queue processing"); From e85debbb261f35918c8e09aa6a4a544f24e02e6f Mon Sep 17 00:00:00 2001 From: Boris Gvozdev Date: Wed, 6 Sep 2023 22:55:11 +1000 Subject: [PATCH 2/4] NONE: remove cycle dep --- src/config/statsd.ts | 11 ++++++++--- src/main.ts | 4 +++- src/worker.ts | 3 +++ 3 files changed, 14 insertions(+), 4 deletions(-) diff --git a/src/config/statsd.ts b/src/config/statsd.ts index a27942e080..cbbd822814 100644 --- a/src/config/statsd.ts +++ b/src/config/statsd.ts @@ -1,10 +1,10 @@ import { StatsD, Tags } from "hot-shots"; -import { getLogger } from "./logger"; import { NextFunction, Request, Response } from "express"; import { isNodeProd, isNodeTest } from "utils/is-node-env"; import { metricHttpRequest } from "./metric-names"; import { envVars } from "./env"; import { isTestJiraHost } from "./jira-test-site-check"; +import Logger from "bunyan"; export const globalTags = { environment: isNodeTest() ? "test" : process.env.MICROS_ENV || "", @@ -14,7 +14,12 @@ export const globalTags = { }; const RESPONSE_TIME_HISTOGRAM_BUCKETS = "100_1000_2000_3000_5000_10000_30000_60000"; -const logger = getLogger("config.statsd"); + +// Not using getLogger() to avoid cyclic dependencies +let logger: Logger | undefined; +export const initStatsdLogger = (loggerArg: Logger) => { + logger = loggerArg; +}; const innerStatsd = new StatsD({ prefix: "github-for-jira.", @@ -23,7 +28,7 @@ const innerStatsd = new StatsD({ globalTags, errorHandler: (err) => { if (isNodeProd()) { - logger.warn(err, "Error writing metrics"); + logger?.warn({ err }, "Error writing metrics"); } }, diff --git a/src/main.ts b/src/main.ts index 91d141fef6..fa30569911 100644 --- a/src/main.ts +++ b/src/main.ts @@ -6,10 +6,12 @@ import { initializeSentry } from "config/sentry"; import { isNodeProd } from "utils/is-node-env"; import { getFrontendApp } from "./app"; import createLag from "event-loop-lag"; -import { statsd } from "config/statsd"; +import { initStatsdLogger, statsd } from "config/statsd"; import { metricPerf } from "config/metric-names"; const start = async () => { + initStatsdLogger(getLogger("config.statsd")); + initializeSentry(); const app: Express = getFrontendApp(); const port = Number(process.env.TUNNEL_PORT) || Number(process.env.PORT) || 8080; diff --git a/src/worker.ts b/src/worker.ts index 53bb4f175d..6200df0374 100755 --- a/src/worker.ts +++ b/src/worker.ts @@ -8,8 +8,11 @@ import { initializeSentry } from "./config/sentry"; import { listenForClusterCommand } from "./services/cluster/listen-command"; import { start, stop } from "./worker/startup"; import { getLogger } from "config/logger"; +import { initStatsdLogger } from "config/statsd"; const initialize = () => { + initStatsdLogger(getLogger("config.statsd")); + initializeSentry(); // starts healthcheck/deepcheck or else deploy will fail const port = Number(process.env.WORKER_PORT) || Number(process.env.PORT) || 8081; From 1b2949c2f876993aeff52436b0c58149b0743f7e Mon Sep 17 00:00:00 2001 From: Boris Gvozdev Date: Wed, 6 Sep 2023 23:09:18 +1000 Subject: [PATCH 3/4] NONE: improve a little bit --- src/config/metric-names.ts | 3 +++ src/config/statsd.ts | 7 ++++++- src/routes/github/webhook/webhook-receiver-post.ts | 4 ++-- src/util/encryption.ts | 8 ++++---- 4 files changed, 15 insertions(+), 7 deletions(-) diff --git a/src/config/metric-names.ts b/src/config/metric-names.ts index 841cda8db1..c70eb4d28a 100644 --- a/src/config/metric-names.ts +++ b/src/config/metric-names.ts @@ -84,10 +84,13 @@ export const metricPrReviewers = { export const metricPerf = { lagHist: `${server}.lag.histogram`, + webhookShaGeneratorHist: `${server}.webhook.sha.generator.histogram`, webhookShaGeneratorCnt: `${server}.webhook.sha.generator.count`, + hashWithSharedSecretHist: `${server}.hash.with.shared.secret.histogram`, hashWithSharedSecretCnt: `${server}.hash.with.shared.secret.count`, + hashWithoutSharedSecretHist: `${server}.hash.without.shared.secret.histogram`, hashWithoutSharedSecretCnt: `${server}.hash.without.shared.secret.count` }; diff --git a/src/config/statsd.ts b/src/config/statsd.ts index cbbd822814..ce497ac96b 100644 --- a/src/config/statsd.ts +++ b/src/config/statsd.ts @@ -28,7 +28,12 @@ const innerStatsd = new StatsD({ globalTags, errorHandler: (err) => { if (isNodeProd()) { - logger?.warn({ err }, "Error writing metrics"); + if (logger) { + logger.warn({ err }, "Error writing metrics"); + } else { + // eslint-disable-next-line no-console + console.error("Error writing metrics", err); + } } }, diff --git a/src/routes/github/webhook/webhook-receiver-post.ts b/src/routes/github/webhook/webhook-receiver-post.ts index f5b48df22d..eb836f5033 100644 --- a/src/routes/github/webhook/webhook-receiver-post.ts +++ b/src/routes/github/webhook/webhook-receiver-post.ts @@ -45,9 +45,9 @@ export const WebhookReceiverPost = async (request: Request, response: Response): const { webhookSecrets, gitHubServerApp } = await getWebhookSecrets(uuid); const isVerified = webhookSecrets.some((secret, index) => { - const started = new Date().getTime(); + const started = Date.now(); const matchesSignature = createHash(request.rawBody, secret) === signatureSHA256; - const finished = new Date().getTime(); + const finished = Date.now(); statsd.histogram(metricPerf.webhookShaGeneratorHist, finished-started, { } ,{ }); statsd.increment(metricPerf.webhookShaGeneratorCnt, { }, { }); diff --git a/src/util/encryption.ts b/src/util/encryption.ts index 6d7a0fc36d..886de19542 100644 --- a/src/util/encryption.ts +++ b/src/util/encryption.ts @@ -8,14 +8,14 @@ export const createHashWithSharedSecret = (data?: string): string => { return ""; } - const started = new Date().getTime(); + const started = Date.now(); try { const cleanedData = removeNonAlphaNumericCharacters(data); return createHmac("sha256", envVars.GLOBAL_HASH_SECRET) .update(cleanedData) .digest("hex"); } finally { - const finished = new Date().getTime(); + const finished = Date.now(); statsd.histogram(metricPerf.hashWithSharedSecretHist, finished-started, { } ,{ }); statsd.increment(metricPerf.hashWithSharedSecretCnt, { }, { }); } @@ -25,11 +25,11 @@ export const createHashWithoutSharedSecret = (data: string | null | undefined) = if (!data) { return ""; } - const started = new Date().getTime(); + const started = Date.now(); try { return createHash("sha256").update(data).digest("hex"); } finally { - const finished = new Date().getTime(); + const finished = Date.now(); statsd.histogram(metricPerf.hashWithoutSharedSecretHist, finished-started, { } ,{ }); statsd.increment(metricPerf.hashWithoutSharedSecretCnt, { }, { }); } From 933d5947b6661d50dc71f3447d7526f22eaeded1 Mon Sep 17 00:00:00 2001 From: Boris Gvozdev Date: Wed, 6 Sep 2023 23:35:14 +1000 Subject: [PATCH 4/4] NONE: fix tests --- src/config/statsd.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/config/statsd.ts b/src/config/statsd.ts index ce497ac96b..c869632f69 100644 --- a/src/config/statsd.ts +++ b/src/config/statsd.ts @@ -103,7 +103,7 @@ export const elapsedTimeMetrics = ( ) => { const elapsedTimeInMs = hrtimer(); const method = req.method; - (req.log || logger).debug({ + (req.log || logger)?.debug({ method: req.method, path: req.path, body: JSON.stringify(req.body), @@ -115,7 +115,7 @@ export const elapsedTimeMetrics = ( const statusCode = `${res.statusCode}`; const path = (req.baseUrl || "") + (req.route?.path || "/*"); const tags = { path, method, statusCode }; - (req.log || logger).debug(`${method} request executed in ${elapsedTime} with status ${statusCode} path ${path}`); + (req.log || logger)?.debug(`${method} request executed in ${elapsedTime} with status ${statusCode} path ${path}`); //Count response time metric innerStatsd.histogram(metricHttpRequest.duration, elapsedTime, tags);