refactor: swap logger

src/app.ts

@@ -4,8 +4,8 @@ import express, { json, urlencoded } from "express";
 import swaggerUi from "swagger-ui-express";
 import swaggerDocument from "./swagger.json";
 import error from "./middlewares/error";
+import morgan from "./middlewares/morgan";
 import { RegisterRoutes } from "./routes";
-import logMiddleware from "./middlewares/log";
 import { addUserRoles, createUser, getRoleByName, listUser } from "./services/keycloak";
 import prisma from "./db";
 
@@ -62,11 +62,17 @@ const APP_PORT = +(process.env.APP_PORT || 3000);
     });
   }
 
+  const originalSend = app.response.json;
+
+  app.response.json = function (body: unknown) {
+    this.app.locals.response = body;
+    return originalSend.call(this, body);
+  };
+
   app.use(cors());
   app.use(json());
   app.use(urlencoded({ extended: true }));
-
-  app.use(logMiddleware);
+  app.use(morgan);
 
   app.use("/", express.static("static"));
   app.use("/api-docs", swaggerUi.serve, swaggerUi.setup(swaggerDocument));

src/middlewares/log.ts

@@ -1,73 +0,0 @@
-import { NextFunction, Request, Response } from "express";
-import elasticsearch from "../services/elasticsearch";
-import { randomUUID } from "crypto";
-
-if (!process.env.ELASTICSEARCH_INDEX) {
-  throw new Error("Require ELASTICSEARCH_INDEX to store log.");
-}
-
-const ELASTICSEARCH_INDEX = process.env.ELASTICSEARCH_INDEX;
-
-const LOG_LEVEL_MAP: Record<string, number> = {
-  debug: 4,
-  info: 3,
-  warning: 2,
-  error: 1,
-  none: 0,
-};
-
-async function logMiddleware(req: Request, res: Response, next: NextFunction) {
-  if (!req.url.startsWith("/api/")) return next();
-
-  let data: any;
-
-  const originalJson = res.json;
-
-  res.json = function (v: any) {
-    data = v;
-    return originalJson.call(this, v);
-  };
-
-  const timestamp = new Date().toISOString();
-  const start = performance.now();
-
-  req.app.locals.logData = {};
-
-  res.on("finish", () => {
-    if (!req.url.startsWith("/api/")) return;
-
-    const level = LOG_LEVEL_MAP[process.env.LOG_LEVEL ?? "info"] || 1;
-
-    if (level === 1 && res.statusCode < 500) return;
-    if (level === 2 && res.statusCode < 400) return;
-    if (level === 3 && res.statusCode < 200) return;
-
-    const obj = {
-      logType: res.statusCode >= 500 ? "error" : res.statusCode >= 400 ? "warning" : "info",
-      systemName: "JWS-SOS",
-      startTimeStamp: timestamp,
-      endTimeStamp: new Date().toISOString(),
-      processTime: performance.now() - start,
-      host: req.hostname,
-      sessionId: req.headers["x-session-id"],
-      rtId: req.headers["x-rtid"],
-      tId: randomUUID(),
-      method: req.method,
-      endpoint: req.url,
-      responseCode: res.statusCode,
-      responseDescription: data?.code,
-      input: (level === 4 && JSON.stringify(req.body, null, 2)) || undefined,
-      output: (level === 4 && JSON.stringify(data, null, 2)) || undefined,
-      ...req.app.locals.logData,
-    };
-
-    elasticsearch.index({
-      index: ELASTICSEARCH_INDEX,
-      document: obj,
-    });
-  });
-
-  return next();
-}
-
-export default logMiddleware;

src/middlewares/logger.ts

@@ -0,0 +1,40 @@
+import winston from "winston";
+import { ElasticsearchTransport } from "winston-elasticsearch";
+import elasticsearch from "../services/elasticsearch";
+
+const logger = winston.createLogger({
+  levels: winston.config.syslog.levels,
+  defaultMeta: { serviceName: "jws-sos" },
+  transports: [
+    new ElasticsearchTransport({
+      level: "info",
+      index: "app-log-test-winston-index",
+      format: winston.format.combine(winston.format.timestamp(), winston.format.json()),
+      client: elasticsearch,
+      transformer: (payload) => {
+        const { logData: additional, ...rest } = payload.meta;
+        return {
+          level: payload.level,
+          ...rest,
+          ...additional,
+          requestBody:
+            process.env.LOG_LEVEL === "debug" ? JSON.stringify(rest.requestBody) : undefined,
+          responseBody:
+            process.env.LOG_LEVEL === "debug" ? JSON.stringify(rest.responseBody) : undefined,
+        };
+      },
+    }),
+    new winston.transports.Console({
+      format: winston.format.combine(
+        winston.format.colorize(),
+        winston.format.timestamp(),
+        winston.format.printf(
+          ({ level, timestamp, logData, responseBody, requestBody, ...payload }) =>
+            `${level} ${timestamp} ${JSON.stringify(Object.assign(payload, logData), null, 4)}`,
+        ),
+      ),
+    }),
+  ],
+});
+
+export default logger;

src/middlewares/morgan.ts

@@ -0,0 +1,69 @@
+import express from "express";
+import morgan from "morgan";
+import logger from "./logger";
+import { randomUUID } from "crypto";
+
+const LOG_LEVEL_MAP: Record<string, number> = {
+  debug: 4,
+  info: 3,
+  warning: 2,
+  error: 1,
+  none: 0,
+};
+
+// log the HTTP method, request URL, response status, and response time.
+const logFormat = `{
+  "requestMethod": ":method",
+  "requestUrl": ":url",
+  "responseStatus": ":status",
+  "responseTime": ":response-time ms",
+  "transactionId": ":transaction-id",
+  "refTransactionId": ":ref-transaction-id",
+  "sessionId": ":session-id",
+  "requestBody": :request-body,
+  "responseBody": :response-body,
+  "logData": :log-data
+}`;
+
+function logMessageHandler(message: string) {
+  const data = JSON.parse(message.trim());
+
+  const level = LOG_LEVEL_MAP[process.env.LOG_LEVEL ?? "info"] || 1;
+  const status = +data.responseStatus;
+
+  if (level === 1 && status < 500) return;
+  if (level === 2 && status < 400) return;
+  if (level === 3 && status < 200) return;
+
+  if (status >= 500) return logger.error("HTTP request received", JSON.parse(message.trim()));
+  if (status >= 400) return logger.warning("HTTP request received", JSON.parse(message.trim()));
+  return logger.info("HTTP request received", JSON.parse(message.trim()));
+}
+
+morgan.token("log-data", (req: express.Request) => {
+  return JSON.stringify(req.app.locals.logData || {});
+});
+morgan.token("request-body", (req: express.Request) => {
+  return JSON.stringify(req.body);
+});
+morgan.token("response-body", (req: express.Request) => {
+  return JSON.stringify(req.app.locals.response || {});
+});
+morgan.token("identity-field", (req: express.Request) => {
+  return req.app.locals.identityField;
+});
+morgan.token("session-id", (req: express.Request) => {
+  return req.headers["x-session-id"] as string | undefined;
+});
+morgan.token("ref-transaction-id", (req: express.Request) => {
+  return req.headers["x-rtid"] as string | undefined;
+});
+morgan.token("transaction-id", () => {
+  return randomUUID();
+});
+
+const loggingMiddleware = morgan(logFormat, {
+  stream: { write: logMessageHandler },
+});
+
+export default loggingMiddleware;