NONE: add profiling around calls to crypto lib

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`
 };
 

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);

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);
 };
 

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<void> => {
 	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,

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, { }, { });
+	}
 
 };
 

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;

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");