Feature: logging wrapper tests

packages/logging-wrapper/.eslintrc.json

@@ -1,17 +1,26 @@
 {
-    "parser": "@typescript-eslint/parser",
-    "extends": [
-      "plugin:@typescript-eslint/recommended",
-      "plugin:prettier/recommended",
-      "eslint:recommended"
-    ],
-    "parserOptions": {
-      "ecmaVersion": 2020,
-      "sourceType": "module"
-    },
-    "rules": {
-    },
-    "env": {
-      "node": true
-    }
+  "parser": "@typescript-eslint/parser",
+  "extends": [
+    "plugin:@typescript-eslint/recommended",
+    "plugin:prettier/recommended",
+    "eslint:recommended"
+  ],
+  "parserOptions": {
+    "ecmaVersion": 2020,
+    "sourceType": "module"
+  },
+  "rules": {
+    "no-unused-vars": "off",
+    "@typescript-eslint/no-unused-vars": [
+      "warn",
+      {
+        "argsIgnorePattern": "^_",
+        "varsIgnorePattern": "^_",
+        "caughtErrorsIgnorePattern": "^_"
+      }
+    ]
+  },
+  "env": {
+    "node": true
   }
+}

packages/logging-wrapper/.gitignore

@@ -0,0 +1,12 @@
+# See https://help.github.com/articles/ignoring-files/ for more about ignoring files.
+
+# dependencies
+/node_modules
+/.pnp
+.pnp.js
+.yarn/install-state.gz
+
+# testing
+/coverage
+
+.tap

packages/logging-wrapper/README.md

@@ -0,0 +1,49 @@
+# Logging Wrapper
+
+This logging wrapper goal is to standardize the records written by our services.
+
+## How to
+
+To use this package two steps are needed:
+- use the `getLoggingConfiguration()` method to get the configuration for the `fastify` server.
+```
+const server = fastify({
+    ...getLoggingConfiguration()
+});
+```
+- after the server is initialized, invoke the `initializeLoggingHooks(server)` to setup the needed `fastify` hooks
+```
+initializeLoggingHooks(server);
+```
+
+That's it! Just log as you usually do!
+
+## Default records
+
+We will have 3 mandatory log entries that will be written for each request the service manages.
+
+Those 3 records are:
+- **New Request**, written when a request is received
+```
+{"level":30,"level_name":"INFO","hostname":"hostname","request_id":"q9Y6NwwbRimle4TxcXRPkQ-0000000000","timestamp":1713868947766,"request":{"scheme":"http","method":"GET","path":"/ping","hostname":"localhost:80","query_params":{},"headers":{"user-agent":"lightMyRequest","host":"localhost:80"},"client_ip":"127.0.0.1","user_agent":"lightMyRequest"},"message":"NEW_REQUEST"}
+```
+- **Response**, containing most of the response data
+```
+{"level":30,"level_name":"INFO","hostname":"hostname","request_id":"q9Y6NwwbRimle4TxcXRPkQ-0000000000","timestamp":1713868947769,"request":{"scheme":"http","method":"GET","path":"/ping","hostname":"localhost:80","query_params":{}},"response":{"status_code":200,"headers":{"content-type":"application/json; charset=utf-8","content-length":"17"}},"message":"RESPONSE"}
+```
+- **API Track**, it contains data about the lifecycle of the request, including errors, if any
+```
+{"level":30,"level_name":"INFO","hostname":"hostname","request_id":"5c_RLAnSS4y9-Q5STsJyiQ-0000000008","timestamp":1713869128434,"request":{"scheme":"http","method":"GET","path":"/this-path-must-not-exist","hostname":"localhost:80","query_params":{"status_code":"404","error_message":"Not Found"}},"response":{"status_code":404,"headers":{"content-type":"application/json; charset=utf-8","content-length":"107"}},"error":{"class":"REQUEST_ERROR","message":"Not Found","code":"FST_ERR_NOT_FOUND"},"message":"API_TRACK"}
+```
+
+### Error record
+
+If an error is thrown, a log entry is automatically written.
+
+```
+{"level":50,"level_name":"ERROR","hostname":"hostname","request_id":"1kPptKhMSeyZ9OwcSwBxhg-0000000008","timestamp":1713869258238,"request":{"scheme":"http","method":"GET","path":"/this-path-must-not-exist","hostname":"localhost:80","query_params":{"status_code":"404","error_message":"Not Found"}},"error":{"class":"REQUEST_ERROR","message":"Not Found","trace":"FastifyError: Not Found..... The whole trace here","code":"FST_ERR_NOT_FOUND"},"message":"ERROR"}
+```
+
+## Additional entries
+
+Additional log entries can be added as needed, but they will include, thanks to this package, common info about the request context that will be useful for future troubleshooting.

packages/logging-wrapper/__tests__/fastify-logging-wrapper.errors.test.ts

@@ -0,0 +1,80 @@
+import { LogErrorClasses } from "../src/logging-wrapper-entities";
+import { t } from "tap";
+import { initializeServer, runErrorTest } from "./helpers/fastify-test-helpers";
+
+t.test("Error data are correctly set", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+  await runErrorTest({
+    server,
+    loggingDestination,
+    inputStatusCode: "500",
+    expectedStatusCode: 500,
+    errorMessage: "WHoooopS!",
+    expectedClass: LogErrorClasses.ServerError,
+  });
+
+  t.end();
+});
+
+t.test("Unknown Error route logs expected values", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+  await runErrorTest({
+    server,
+    loggingDestination,
+    inputStatusCode: "399",
+    expectedStatusCode: 500,
+    errorMessage: "Unknown!",
+    expectedClass: LogErrorClasses.UnknownError,
+  });
+
+  t.end();
+});
+
+t.test("400 Error route logs expected values", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+  await runErrorTest({
+    server,
+    loggingDestination,
+    inputStatusCode: "400",
+    expectedStatusCode: 400,
+    errorMessage: "Bad request!",
+    expectedClass: LogErrorClasses.RequestError,
+  });
+
+  t.end();
+});
+
+t.test("422 Validation Error route logs expected values", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+  await runErrorTest({
+    server,
+    loggingDestination,
+    inputStatusCode: "422",
+    expectedStatusCode: 422,
+    errorMessage: "Bad request!",
+    expectedClass: LogErrorClasses.ValidationError,
+  });
+
+  t.end();
+});
+
+t.test("Not found route logs expected values", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+  await runErrorTest({
+    server,
+    loggingDestination,
+    inputStatusCode: "404",
+    expectedStatusCode: 404,
+    errorMessage: "Not Found",
+    expectedClass: LogErrorClasses.RequestError,
+    path: "/this-path-must-not-exist",
+    expectedFastifyCode: "FST_ERR_NOT_FOUND",
+  });
+
+  t.end();
+});

packages/logging-wrapper/__tests__/fastify-logging-wrapper.test.ts

@@ -0,0 +1,123 @@
+import { LogMessages } from "../src/logging-wrapper-entities";
+import { t } from "tap";
+import {
+  initializeServer,
+  DEFAULT_METHOD,
+  DEFAULT_PATH,
+  checkExpectedRequestEntry,
+  checkExpectedResponseEntry,
+  parseLogEntry,
+  checkGenericEntryFields,
+} from "./helpers/fastify-test-helpers";
+
+t.test(
+  "Logging entries when all works fine are the expected ones",
+  async () => {
+    const { server, loggingDestination } = initializeServer();
+    t.teardown(() => server.close());
+
+    const response = await server.inject({
+      method: DEFAULT_METHOD,
+      url: DEFAULT_PATH,
+    });
+    t.ok(typeof response !== "undefined");
+    t.equal(response?.statusCode, 200);
+    const loggedRecords = loggingDestination.getLoggedRecords();
+    t.equal(loggedRecords.length, 3);
+    checkExpectedRequestEntry({
+      requestLogEntry: loggedRecords[0],
+    });
+    checkExpectedResponseEntry({
+      responseLogEntry: loggedRecords[1],
+      responseStatusCode: 200,
+    });
+    checkExpectedResponseEntry({
+      responseLogEntry: loggedRecords[2],
+      responseStatusCode: 200,
+      expectedMessage: LogMessages.ApiTrack,
+    });
+
+    t.end();
+  },
+);
+
+t.test("Request id is not overriden by header", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+  const customRequestId = "Another request id";
+  const response = await server.inject({
+    method: DEFAULT_METHOD,
+    url: DEFAULT_PATH,
+    headers: { "request-id": customRequestId },
+  });
+  t.ok(typeof response !== "undefined");
+  t.equal(response?.statusCode, 200);
+  const logged = loggingDestination.getLoggedRecords();
+  checkExpectedRequestEntry({
+    requestLogEntry: logged[0],
+    inputHeaders: { "request-id": customRequestId },
+  });
+  const parsedEntry = parseLogEntry(logged[0]);
+  t.notSame(parsedEntry.request_id, customRequestId);
+
+  t.end();
+});
+
+t.test("Logging context is reset between requests", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+
+  let response = await server.inject({
+    method: DEFAULT_METHOD,
+    url: DEFAULT_PATH,
+  });
+
+  t.ok(typeof response !== "undefined");
+  t.equal(response?.statusCode, 200);
+  let loggedRecords = loggingDestination.getLoggedRecords();
+  t.equal(loggedRecords.length, 3);
+  let parsedResponse = parseLogEntry(loggedRecords[1]);
+  t.ok(typeof parsedResponse.response !== "undefined");
+
+  response = await server.inject({
+    method: DEFAULT_METHOD,
+    url: DEFAULT_PATH,
+  });
+  t.ok(typeof response !== "undefined");
+  t.equal(response?.statusCode, 200);
+  loggedRecords = loggingDestination.getLoggedRecords();
+  t.equal(loggedRecords.length, 6);
+  // 3 is the New Request for 2nd call
+  parsedResponse = parseLogEntry(loggedRecords[3]);
+  // if undefined it means that the logging context
+  // has been reset between requests
+  t.ok(typeof parsedResponse.response === "undefined");
+
+  t.end();
+});
+
+t.test("Additional logs are correctly written", async () => {
+  const { server, loggingDestination } = initializeServer();
+  t.teardown(() => server.close());
+  const logMessage = "Testing additional logs";
+
+  const response = await server.inject({
+    method: "POST",
+    url: "/logs",
+    body: { log_entry: logMessage },
+  });
+
+  t.ok(typeof response !== "undefined");
+  t.equal(response?.statusCode, 200);
+  const loggedRecords = loggingDestination.getLoggedRecords();
+  t.equal(loggedRecords.length, 4);
+  const parsedAdditional = parseLogEntry(loggedRecords[1]);
+  checkGenericEntryFields({
+    parsedEntry: parsedAdditional,
+    expectedLevelName: "INFO",
+    expectedMessage: logMessage,
+  });
+  t.ok(typeof parsedAdditional.request !== "undefined");
+
+  t.end();
+});

packages/logging-wrapper/__tests__/helpers/build-fastify.ts

@@ -0,0 +1,42 @@
+import Fastify from "fastify";
+import {
+  getLoggingConfiguration,
+  initializeLoggingHooks,
+} from "../../src/fastify-logging-wrapper";
+import { DestinationStream } from "pino";
+import { createError } from "@fastify/error";
+
+export const buildFastify = (loggerDestination?: DestinationStream) => {
+  const server = Fastify({
+    ...getLoggingConfiguration(loggerDestination),
+  });
+
+  initializeLoggingHooks(server);
+
+  server.get("/ping", async (_request, _reply) => {
+    return { data: "pong\n" };
+  });
+
+  server.get("/error", async (request, _reply) => {
+    const parsed = request.query as { [x: string]: unknown };
+    const requestedStatusCode = Number(parsed["status_code"] ?? "500");
+    const requestedMessage = parsed["error_message"] ?? "WHOOOPS";
+
+    throw createError(
+      "CUSTOM_CODE",
+      requestedMessage as string,
+      requestedStatusCode as number,
+    )();
+  });
+
+  server.post("/logs", async (request, _reply) => {
+    const body = request.body as { [x: string]: unknown };
+    const logMessage = body.log_entry ?? "Default additional message";
+
+    request.log.info(logMessage);
+
+    return { data: { message: logMessage } };
+  });
+
+  return server;
+};

packages/logging-wrapper/__tests__/helpers/build-logger.ts

@@ -0,0 +1,28 @@
+import { PinoLoggerOptions } from "fastify/types/logger";
+import { pino } from "pino";
+
+export const buildLogger = (loggerConfiguration: PinoLoggerOptions) => {
+  const { loggerDestination, getLoggedRecords } = getTestingDestinationLogger();
+
+  return {
+    logger: pino(loggerConfiguration, loggerDestination),
+    loggedRecordsMethod: getLoggedRecords,
+  };
+};
+
+export interface TestingLoggerDestination {
+  loggerDestination: {
+    write: (_data: string) => number;
+  };
+  getLoggedRecords: () => string[];
+}
+
+export const getTestingDestinationLogger = (): TestingLoggerDestination => {
+  const testCaseRecords: string[] = [];
+  const getLoggedRecords = () => testCaseRecords;
+  const loggerDestination = {
+    write: (data: string) => testCaseRecords.push(data),
+  };
+
+  return { loggerDestination, getLoggedRecords };
+};