diff --git a/src/config/metric-names.ts b/src/config/metric-names.ts index 40b8b33828..c70eb4d28a 100644 --- a/src/config/metric-names.ts +++ b/src/config/metric-names.ts @@ -82,7 +82,16 @@ 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/config/statsd.ts b/src/config/statsd.ts index a27942e080..c869632f69 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,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); + } } }, @@ -93,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), @@ -105,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); diff --git a/src/main.ts b/src/main.ts index 0fda8f4817..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 { metricLag } from "config/metric-names"; +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; @@ -18,7 +20,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..eb836f5033 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 = Date.now(); const matchesSignature = createHash(request.rawBody, secret) === signatureSHA256; + const finished = Date.now(); + + 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..886de19542 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 = Date.now(); + try { + const cleanedData = removeNonAlphaNumericCharacters(data); + return createHmac("sha256", envVars.GLOBAL_HASH_SECRET) + .update(cleanedData) + .digest("hex"); + } finally { + const finished = Date.now(); + 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 = Date.now(); + try { + return createHash("sha256").update(data).digest("hex"); + } finally { + const finished = Date.now(); + statsd.histogram(metricPerf.hashWithoutSharedSecretHist, finished-started, { } ,{ }); + statsd.increment(metricPerf.hashWithoutSharedSecretCnt, { }, { }); + } }; 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; 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");