use structured logging for email utils (#5230)

rhelmer · Vinnl · web-flow · commit 77df206d0a5a · 2024-10-25T13:25:23.000-07:00
* use structured logging for email utils
* add module name mapping for uuid and jest

---------

Co-authored-by: Vincent &lt;git@vincenttunru.com&gt;
diff --git a/jest.config.cjs b/jest.config.cjs
@@ -113,7 +113,10 @@ const customJestConfig = {
   // ],
 
   // A map from regular expressions to module names or to arrays of module names that allow to stub out resources with a single module
-  // moduleNameMapper: {},
+  moduleNameMapper: {
+    // Force module uuid to resolve with the CJS entry point, because Jest does not support package.json.exports. See https://github.com/uuidjs/uuid/issues/451
+    uuid: require.resolve("uuid"),
+  },
 
   // An array of regexp pattern strings, matched against all module paths before considered 'visible' to the module loader
   modulePathIgnorePatterns: ["e2e/"],
diff --git a/src/app/functions/server/logging.ts b/src/app/functions/server/logging.ts
@@ -16,6 +16,7 @@ export const logger = createLogger({
   level: "info",
   // In GCP environments, use cloud logging instead of stdout.
   // FIXME https://mozilla-hub.atlassian.net/browse/MNTOR-2401 - enable for stage and production
+  /* c8 ignore next 3 - cannot test this outside of GCP currently */
   transports: ["gcpdev"].includes(process.env.APP_ENV ?? "local")
     ? [loggingWinston]
     : [new transports.Console()],
diff --git a/src/utils/email.test.ts b/src/utils/email.test.ts
@@ -5,13 +5,24 @@
 import { test, expect, jest } from "@jest/globals";
 import type { createTransport, Transporter } from "nodemailer";
 import { randomToken } from "./email";
+import type * as loggerModule from "../app/functions/server/logging";
 
 jest.mock("nodemailer", () => {
   return {
     createTransport: jest.fn(),
   };
 });
 
+jest.mock("../app/functions/server/logging", () => {
+  return {
+    logger: {
+      info: jest.fn(),
+      warn: jest.fn(),
+      error: jest.fn(),
+    },
+  };
+});
+
 test("EmailUtils.sendEmail before .init() fails", async () => {
   expect.assertions(1);
 
@@ -25,9 +36,9 @@ test("EmailUtils.sendEmail before .init() fails", async () => {
 });
 
 test("EmailUtils.init with empty host uses jsonTransport", async () => {
-  const mockedConsoleInfo = jest
-    .spyOn(console, "info")
-    .mockImplementation(() => undefined);
+  const mockedLoggerModule = jest.requireMock<typeof loggerModule>(
+    "../app/functions/server/logging",
+  );
   const mockedNodemailer: {
     createTransport: jest.MockedFunction<typeof createTransport>;
   } = jest.requireMock("nodemailer");
@@ -37,7 +48,7 @@ test("EmailUtils.init with empty host uses jsonTransport", async () => {
   expect(mockedNodemailer.createTransport).toHaveBeenCalledWith({
     jsonTransport: true,
   });
-  expect(mockedConsoleInfo).toHaveBeenCalledWith("smtpUrl-empty", {
+  expect(mockedLoggerModule.logger.info).toHaveBeenCalledWith("smtpUrl-empty", {
     message: "EmailUtils will log a JSON response instead of sending emails.",
   });
 });
@@ -65,9 +76,9 @@ test("EmailUtils.sendEmail with recipient, subject, template, context calls gTra
   const mockedNodemailer: {
     createTransport: jest.MockedFunction<typeof createTransport>;
   } = jest.requireMock("nodemailer");
-  const mockedConsoleInfo = jest
-    .spyOn(console, "info")
-    .mockImplementation(() => undefined);
+  const mockedLoggerModule = jest.requireMock<typeof loggerModule>(
+    "../app/functions/server/logging",
+  );
   const { initEmail, sendEmail } = await import("./email");
 
   const testSmtpUrl = "smtps://test:test@test:1";
@@ -86,13 +97,16 @@ test("EmailUtils.sendEmail with recipient, subject, template, context calls gTra
   expect(
     await sendEmail("test@example.com", "subject", "<html>test</html>"),
   ).toBe(sendMailInfo);
-  expect(mockedConsoleInfo).toHaveBeenCalledWith("sent_email", sendMailInfo);
+  expect(mockedLoggerModule.logger.info).toHaveBeenCalledWith(
+    "sent_email",
+    sendMailInfo,
+  );
 });
 
 test("EmailUtils.sendEmail rejects with error", async () => {
-  const mockedConsoleError = jest
-    .spyOn(console, "error")
-    .mockImplementation(() => undefined);
+  const mockedLoggerModule = jest.requireMock<typeof loggerModule>(
+    "../app/functions/server/logging",
+  );
   const mockedNodemailer: {
     createTransport: jest.MockedFunction<typeof createTransport>;
   } = jest.requireMock("nodemailer");
@@ -109,16 +123,16 @@ test("EmailUtils.sendEmail rejects with error", async () => {
   await expect(() =>
     sendEmail("test@example.com", "subject", "<html>test</html>"),
   ).rejects.toThrow("error");
-  expect(mockedConsoleError).toHaveBeenCalled();
+  expect(mockedLoggerModule.logger.error).toHaveBeenCalled();
 });
 
 test("EmailUtils.init with empty host uses jsonTransport. logs messages", async () => {
   const mockedNodemailer: {
     createTransport: jest.MockedFunction<typeof createTransport>;
   } = jest.requireMock("nodemailer");
-  const mockedConsoleInfo = jest
-    .spyOn(console, "info")
-    .mockImplementation(() => undefined);
+  const mockedLoggerModule = jest.requireMock<typeof loggerModule>(
+    "../app/functions/server/logging",
+  );
   const { initEmail, sendEmail } = await import("./email");
 
   const sendMailInfo = { messageId: "test id", response: "test response" };
@@ -134,7 +148,10 @@ test("EmailUtils.init with empty host uses jsonTransport. logs messages", async
   expect(
     await sendEmail("test@example.com", "subject", "<html>test</html>"),
   ).toBe(sendMailInfo);
-  expect(mockedConsoleInfo).toHaveBeenCalledWith("sent_email", sendMailInfo);
+  expect(mockedLoggerModule.logger.info).toHaveBeenCalledWith(
+    "sent_email",
+    sendMailInfo,
+  );
 });
 
 test("randomToken returns a random token of 2xlength (because of hex)", () => {
diff --git a/src/utils/email.ts b/src/utils/email.ts
@@ -7,6 +7,7 @@ import crypto from "crypto";
 
 import { SentMessageInfo } from "nodemailer/lib/smtp-transport/index.js";
 import { getEnvVarsOrThrow } from "../envVars";
+import { logger } from "../app/functions/server/logging";
 
 // The SMTP transport object. This is initialized to a nodemailer transport
 // object while reading SMTP credentials, or to a dummy function in debug mode.
@@ -17,7 +18,7 @@ const envVars = getEnvVarsOrThrow(["SMTP_URL", "EMAIL_FROM", "SES_CONFIG_SET"]);
 async function initEmail(smtpUrl = envVars.SMTP_URL) {
   // Allow a debug mode that will log JSON instead of sending emails.
   if (!smtpUrl) {
-    console.info("smtpUrl-empty", {
+    logger.info("smtpUrl-empty", {
       message: "EmailUtils will log a JSON response instead of sending emails.",
     });
     gTransporter = createTransport({ jsonTransport: true });
@@ -62,24 +63,24 @@ async function sendEmail(
     /* c8 ignore next 5 */
     if (gTransporter.transporter.name === "JSONTransport") {
       // @ts-ignore Added typing later, but it disagrees with actual use:
-      console.info("JSONTransport", { message: info.message.toString() });
+      logger.info("JSONTransport", { message: info.message.toString() });
       return info;
     }
 
-    console.info("sent_email", {
+    logger.info("sent_email", {
       messageId: info.messageId,
       response: info.response,
     });
     return info;
   } catch (e) {
     if (e instanceof Error) {
-      console.error("error_sending_email", {
+      logger.error("error_sending_email", {
         message: e.message,
         stack: e.stack,
       });
       /* c8 ignore next 3 */
     } else {
-      console.error("error_sending_email", { message: JSON.stringify(e) });
+      logger.error("error_sending_email", { message: JSON.stringify(e) });
     }
     throw e;
   }
