Merge pull request #301 from IBM/logging

Logging examples

Author: reggeenr

cos-to-sql/app.mjs

@@ -1,4 +1,5 @@
 import { stat } from "fs/promises";
+import crypto from "crypto";
 import express from "express";
 import favicon from "serve-favicon";
 import path from "path";
@@ -15,8 +16,11 @@ import { ContainerAuthenticator } from "ibm-cloud-sdk-core";
 import { addUser, closeDBConnection, deleteUsers, getPgClient, listUsers } from "./utils/db.mjs";
 import { getObjectContent } from "./utils/cos.mjs";
 import { convertCsvToDataStruct } from "./utils/utils.mjs";
+import { getCodeEngineLogger } from "./utils/logging.mjs";
 
-console.info("Starting the app ...");
+const appLogger = getCodeEngineLogger("app");
+
+appLogger.info("Starting the app ...");
 
 const requiredEnvVars = [
   "COS_REGION",
@@ -28,7 +32,7 @@ const requiredEnvVars = [
 
 requiredEnvVars.forEach((envVarName) => {
   if (!process.env[envVarName]) {
-    console.log(`Failed to start app. Missing '${envVarName}' environment variable`);
+    appLogger.warn(`Failed to start app. Missing '${envVarName}' environment variable`);
     process.exit(1);
   }
 });
@@ -60,18 +64,42 @@ const app = express();
 app.use(express.json());
 app.use(favicon(path.join(__dirname, "public", "favicon.ico")));
 
+// helper function to send JSON responses
+function sendJSONResponse(request, response, returnCode, jsonObject) {
+  response.status(returnCode);
+  response.setHeader("Content-Type", "application/json");
+  response.end(JSON.stringify(jsonObject));
+  const duration = Date.now() - request.startTime;
+  request.logger.info(`handled ${request.method} request for '${request.path}' in ${duration}ms; rc: '${returnCode}'`, {
+    returnCode,
+    duration_ms: duration,
+  });
+}
+
 // use router to bundle all routes to /
 const router = express.Router();
+
+// adding a middleware that extracts the correlation id and initializes the logger
+router.use((req, res, next) => {
+  const correlationId = req.header("x-request-id") || crypto.randomBytes(8).toString("hex");
+  req.startTime = Date.now();
+  req.correlationId = correlationId;
+  const operationId = `${req.method}:${req.path}`;
+  req.operationId = operationId;
+  req.logger = getCodeEngineLogger("handle-request").child({ correlationId, operationId });
+  req.logger.info(`handling incoming ${req.method} request for '${req.path}'`);
+  next();
+});
+
 app.use("/", router);
 
 //
 // Default http endpoint, which prints the list of all users in the database
 router.get("/", async (req, res) => {
-  console.log(`handling / for '${req.url}'`);
   const pgClient = await getPgClient(secretsManager, smPgSecretId);
   const allUsers = await listUsers(pgClient);
-  res.writeHead(200, { "Content-Type": "application/json" });
-  res.end(JSON.stringify({ users: allUsers.rows }));
+
+  return sendJSONResponse(req, res, 200, { users: allUsers.rows });
 });
 
 //
@@ -80,111 +108,102 @@ router.get("/readiness", async (req, res) => {
   console.log(`handling /readiness`);
   if (!(await stat("/var/run/secrets/codeengine.cloud.ibm.com/compute-resource-token/token"))) {
     console.error("Mounting the trusted profile compute resource token is not enabled");
-    res.writeHead(500, { "Content-Type": "application/json" });
-    res.end('{"error": "Mounting the trusted profile compute resource token is not enabled"}');
-    return;
+
+    return sendJSONResponse(req, res, 500, {
+      error: "Mounting the trusted profile compute resource token is not enabled",
+    });
   }
 
-  res.writeHead(200, { "Content-Type": "application/json" });
-  res.end('{"status": "ok"}');
-  return;
+  return sendJSONResponse(req, res, 200, { status: "ok" });
 });
 
 //
 // Ingestion endpoint
 router.post("/cos-to-sql", async (req, res) => {
-  console.log(`handling /cos-to-sql for '${req.url}'`);
-  console.log(`request headers: '${JSON.stringify(req.headers)}`);
+  req.logger.debug(`request headers: '${JSON.stringify(req.headers)}`);
   const event = req.body;
-  console.log(`request body: '${event}'`);
+  req.logger.debug(`request body: '${event}'`);
 
   //
   // assess whether the request payload contains information about the COS file that got updated
   if (!event) {
-    console.log("Request does not contain any event data");
-    res.writeHead(400, { "Content-Type": "application/json" });
-    res.end('{"error": "request does not contain any event data"}');
-    return;
+    req.logger.info("Request does not contain any event data");
+    return sendJSONResponse(req, res, 400, { error: "request does not contain any event data" });
   }
 
   //
   // make sure that the event relates to a COS write operation
   if (event.notification.event_type !== "Object:Write") {
-    console.log(`COS operation '${event.notification.event_type}' does not match expectations 'Object:Write'`);
-    res.writeHead(400, { "Content-Type": "application/json" });
-    res.end(`{"error": "COS operation '${event.notification.event_type}' does not match expectations 'Object:Write'"}`);
-    return;
+    req.logger.info(`COS operation '${event.notification.event_type}' does not match expectations 'Object:Write'`);
+
+    return sendJSONResponse(req, res, 400, {
+      error: `COS operation '${event.notification.event_type}' does not match expectations 'Object:Write'`,
+    });
   }
   if (event.notification.content_type !== "text/csv") {
-    console.log(
+    req.logger.info(
       `COS update did happen on file '${event.key}' which is of type '${event.notification.content_type}' (expected type 'text/csv')`
     );
-    res.writeHead(400, { "Content-Type": "application/json" });
-    res.end(
-      `{"error": "COS update did happen on file '${event.key}' which is of type '${event.notification.content_type}' (expected type 'text/csv')"}`
-    );
-    return;
+
+    return sendJSONResponse(req, res, 400, {
+      error: `COS update did happen on file '${event.key}' which is of type '${event.notification.content_type}' (expected type 'text/csv')`,
+    });
   }
-  console.log(`Received a COS update event on the CSV file '${event.key}' in bucket '${event.bucket}'`);
+  req.logger.info(`Received a COS update event on the CSV file '${event.key}' in bucket '${event.bucket}'`);
 
   //
   // Retrieve the COS object that got updated
-  console.log(`Retrieving file content of '${event.key}' from bucket ${event.bucket} ...`);
+  req.logger.info(`Retrieving file content of '${event.key}' from bucket ${event.bucket} ...`);
   const fileContent = await getObjectContent(cosAuthenticator, cosRegion, event.bucket, event.key);
 
   //
   // Convert CSV to a object structure representing an array of users
-  console.log(`Converting CSV data to a data struct ...`);
+  req.logger.info(`Converting CSV data to a data struct ...`);
   const users = await convertCsvToDataStruct(fileContent);
-  console.log(`users: ${JSON.stringify(users)}`);
+  req.logger.info(`users: ${JSON.stringify(users)}`);
 
   const pgClient = await getPgClient(secretsManager, smPgSecretId);
 
   //
   // Iterate through the list of users
-  console.log(`Writing converted CSV data to the PostgreSQL database ...`);
+  req.logger.info(`Writing converted CSV data to the PostgreSQL database ...`);
   let numberOfProcessedUsers = 0;
   for (const userToAdd of users) {
     try {
       // Perform a single SQL insert statement per user
       const result = await addUser(pgClient, userToAdd.Firstname, userToAdd.Lastname);
-      console.log(`Added ${JSON.stringify(userToAdd)} -> ${JSON.stringify(result)}`);
+      req.logger.info(`Added ${JSON.stringify(userToAdd)} -> ${JSON.stringify(result)}`);
       numberOfProcessedUsers++;
     } catch (err) {
-      console.error(`Failed to add user '${JSON.stringify(userToAdd)}' to the database`, err);
+      req.logger.error(`Failed to add user '${JSON.stringify(userToAdd)}' to the database`, err);
     }
   }
 
-  console.log(`Processed ${numberOfProcessedUsers} user records!`);
-  res.writeHead(200, { "Content-Type": "application/json" });
-  res.end(`{"status": "done"}`);
-  return;
+  req.logger.info(`Processed ${numberOfProcessedUsers} user records!`);
+  return sendJSONResponse(req, res, 200, { status: "done" });
 });
 
 //
 // Endpoint that drops the users table
 router.get("/clear", async (req, res) => {
-  console.log(`handling /clear for '${req.url}'`);
   const pgClient = await getPgClient(secretsManager, smPgSecretId);
   await deleteUsers(pgClient);
-  console.log(`Deletions done!`);
-  res.writeHead(200, { "Content-Type": "application/json" });
-  res.end(`{"status": "done"}`);
-  return;
+  req.logger.info(`Deletions done!`);
+  return sendJSONResponse(req, res, 200, { status: "done" });
 });
 
 // start server
 const port = 8080;
 const server = app.listen(port, () => {
-  console.log(`Server is up and running on port ${port}!`);
+  appLogger.info(`Server is up and running on port ${port}!`);
 });
 
 process.on("SIGTERM", async () => {
-  console.info("SIGTERM signal received.");
+  appLogger.info("SIGTERM signal received.");
 
   await closeDBConnection();
 
   server.close(() => {
-    console.log("Http server closed.");
+    appLogger.info("Http server closed.");
   });
 });