logs: create context logger for each request

bin/democratic-csi

@@ -118,6 +118,7 @@ const cache = new LRU({ max: 500 });
 const { logger } = require("../src/utils/logger");
 const { GrpcError } = require("../src/utils/grpc");
 const GeneralUtils = require("../src/utils/general");
+const uuidv4 = require("uuid").v4;
 
 if (args.logLevel) {
   logger.level = args.logLevel;
@@ -178,17 +179,25 @@ async function requestHandlerProxy(call, callback, serviceMethodName) {
     }
   }
 
+  const requestReadableID = GeneralUtils.loggerIdFromRequest(call, serviceMethodName);
+  const requestUUID = uuidv4();
+  const callContext = {
+    logger: logger.child({
+      method: serviceMethodName,
+      requestId: requestReadableID,
+      uuid: requestUUID,
+    }),
+  };
   try {
-    logger.info(
+    callContext.logger.info(
-      "new request - driver: %s method: %s call: %j",
+      "new request: driver: %s, call: %j",
       driver.constructor.name,
-      serviceMethodName,
       cleansedCall
     );
 
     const lockKeys = GeneralUtils.lockKeysFromRequest(call, serviceMethodName);
     if (lockKeys.length > 0) {
-      logger.debug("operation lock keys: %j", lockKeys);
+      callContext.logger.debug("operation lock keys: %j", lockKeys);
       // check locks
       lockKeys.forEach((key) => {
         if (operationLock.has(key)) {
@@ -216,7 +225,7 @@ async function requestHandlerProxy(call, callback, serviceMethodName) {
     let response;
     let responseError;
     try {
-      // aquire locks
+      // acquire locks
       if (lockKeys.length > 0) {
         lockKeys.forEach((key) => {
           operationLock.add(key);
@@ -246,10 +255,8 @@ async function requestHandlerProxy(call, callback, serviceMethodName) {
       );
     }
 
-    logger.info(
+    callContext.logger.info(
-      "new response - driver: %s method: %s response: %j",
+      "new response: %j",
-      driver.constructor.name,
-      serviceMethodName,
       response
     );
 
@@ -265,10 +272,8 @@ async function requestHandlerProxy(call, callback, serviceMethodName) {
       message = stringify(e);
     }
 
-    logger.error(
+    callContext.logger.error(
-      "handler error - driver: %s method: %s error: %s",
+      "handler error: %s",
-      driver.constructor.name,
-      serviceMethodName,
       message
     );
 

src/utils/general.js

@@ -92,6 +92,49 @@ function lockKeysFromRequest(call, serviceMethodName) {
   }
 }
 
+function loggerIdFromRequest(call, serviceMethodName) {
+  switch (serviceMethodName) {
+    // controller
+    case "CreateVolume":
+      return call.request.name;
+    case "DeleteVolume":
+    case "ControllerExpandVolume":
+    case "ControllerPublishVolume":
+    case "ControllerUnpublishVolume":
+    case "ValidateVolumeCapabilities":
+    case "ControllerGetVolume":
+    case "ControllerModifyVolume":
+      return call.request.volume_id;
+    case "CreateSnapshot":
+      return call.request.source_volume_id;
+    case "DeleteSnapshot":
+      return call.request.snapshot_id;
+    case "ListVolumes":
+    case "GetCapacity":
+    case "ControllerGetCapabilities":
+    case "ListSnapshots":
+      return '';
+
+    // node
+    case "NodeStageVolume":
+    case "NodeUnstageVolume":
+    case "NodePublishVolume":
+    case "NodeUnpublishVolume":
+    case "NodeGetVolumeStats":
+    case "NodeExpandVolume":
+      return call.request.volume_id;
+
+    case "NodeGetCapabilities":
+    case "NodeGetInfo":
+    case "GetPluginInfo":
+    case "GetPluginCapabilities":
+    case "Probe":
+      return '';
+    default:
+      throw `loggerIdFromRequest: unknown method: ${serviceMethodName}`;
+  }
+}
+
 function getLargestNumber() {
   let number;
   for (let i = 0; i < arguments.length; i++) {
@@ -278,6 +321,7 @@ module.exports.crc32 = crc32;
 module.exports.crc16 = crc16;
 module.exports.crc8 = crc8;
 module.exports.lockKeysFromRequest = lockKeysFromRequest;
+module.exports.loggerIdFromRequest = loggerIdFromRequest;
 module.exports.getLargestNumber = getLargestNumber;
 module.exports.stringify = stringify;
 module.exports.before_string = before_string;