Merge pull request #470 from SquirrelCorporation/chore-refacto-logs

[CHORE] Enhance logging and error messages with device context

server/src/controllers/rest/playbooks/hook.ts

@@ -22,12 +22,10 @@ export const addTaskStatus = async (req, res) => {
     });
     if (isFinalStatus(status)) {
       if (ansibleTask.target && ansibleTask.target.length > 0) {
-        logger.warn('Removing temporary private key');
         ansibleTask.target?.map((e) =>
           sshPrivateKeyFileManager.removeAnsibleTemporaryPrivateKey(e, ident),
         );
       } else {
-        logger.warn('Removing temporary private keys');
         sshPrivateKeyFileManager.removeAllAnsibleExecTemporaryPrivateKeys(ident);
       }
     }

server/src/core/events/EventManager.ts

@@ -25,7 +25,7 @@ abstract class EventManager {
 
   protected constructor() {
     this.eventListeners = {};
-    this.logger = log.child({ module: 'EventManager' }, { msgPrefix: '[EVENT-MANAGER] - ' });
+    this.logger = log.child({ module: 'EventManager' }, { msgPrefix: '[EVENT_MANAGER] - ' });
   }
 
   private initializeEventListener(event: string) {

server/src/core/startup/index.ts

@@ -21,9 +21,9 @@ import { setAnsibleVersions } from '../system/ansible-versions';
 
 class Startup {
   private logger = PinoLogger.child({ module: 'Startup' }, { msgPrefix: '[STARTUP] - ' });
-  private static readonly MODULE_STARTUP = '[STARTUP]';
 
   async init() {
+    this.logger.info(`Initializing...`);
     const schemeVersion = await this.initializeSchemeVersion();
     await this.initializeModules();
     if (this.isSchemeVersionDifferent(schemeVersion)) {
@@ -33,8 +33,7 @@ class Startup {
 
   private async initializeSchemeVersion(): Promise<string | null> {
     const schemeVersion = await getFromCache(SettingsKeys.GeneralSettingsKeys.SCHEME_VERSION);
-    this.logger.info(`initialization`);
-    this.logger.info(`${Startup.MODULE_STARTUP} - Scheme Version: ${schemeVersion}`);
+    this.logger.info(`initializeSchemeVersion - Saved scheme version: ${schemeVersion}`);
     return schemeVersion;
   }
 
@@ -50,7 +49,7 @@ class Startup {
   }
 
   private async updateScheme() {
-    this.logger.warn(`Scheme version differed, starting writing updates`);
+    this.logger.warn(`updateScheme- Scheme version differed, starting applying updates...`);
     await PlaybookModel.syncIndexes();
     await DeviceModel.syncIndexes();
     await createADefaultLocalUserRepository();

server/src/data/cache/defaults/index.ts

@@ -1,7 +1,9 @@
 import { SettingsKeys } from 'ssm-shared-lib';
-import logger from '../../../logger';
+import pinoLogger from '../../../logger';
 import { setToCache } from '../index';
 
+const logger = pinoLogger.child({ module: 'Cache' }, { msgPrefix: '[CACHE] - ' });
+
 const REDIS_DEFAULT_VALUES: { key: string; value: string; nx: boolean }[] = [
   {
     key: SettingsKeys.GeneralSettingsKeys.SCHEME_VERSION,
@@ -57,9 +59,7 @@ const REDIS_DEFAULT_VALUES: { key: string; value: string; nx: boolean }[] = [
 
 async function initRedisValues(force?: boolean) {
   for (const value of REDIS_DEFAULT_VALUES) {
-    logger.info(
-      `[REDIS] - initRedisValues - Setting default configuration ${value.key} to ${value.value}`,
-    );
+    logger.info(`initRedisValues - Setting default configuration ${value.key} to ${value.value}`);
     await setToCache(value.key, value.value, {
       NX: force ? false : value.nx,
     });

server/src/data/cache/index.ts

@@ -6,18 +6,19 @@ let redisClient: RedisClientType;
 let isReady: boolean = false;
 
 export const dbURI = `redis://${redisConf.host}:${redisConf.port}`;
-const childLogger = logger.child({ module: 'redis' }, { msgPrefix: '[REDIS] - ' });
+const childLogger = logger.child({ module: 'Cache' }, { msgPrefix: '[CACHE] - ' });
 
 async function createRedisClient(): Promise<any> {
+  logger.info(`createRedisClient - Connecting to ${dbURI}`);
   const redisClient = createClient({
     url: dbURI,
   });
   redisClient
-    .on('error', (err) => childLogger.error('Redis Client Error', err))
-    .on('connect', () => childLogger.info('Successfully connected to Redis'))
+    .on('error', (err) => childLogger.error(`createRedisClient- Client error: ${err.message}`))
+    .on('connect', () => childLogger.info('createRedisClient - Successfully connected to cache'))
     .on('ready', () => {
       isReady = true;
-      childLogger.info(' Redis ready');
+      childLogger.info('createRedisClient - Cache ready');
     });
 
   await redisClient.connect();

server/src/data/database/index.ts

@@ -1,8 +1,9 @@
 import mongoose from 'mongoose';
 import { db } from '../../config';
-import logger from '../../logger';
+import PinoLogger from '../../logger';
 
 export const dbURI = `mongodb://${db.host}:${db.port}/${db.name}`;
+const logger = PinoLogger.child({ module: 'Database' }, { msgPrefix: '[DATABASE] - ' });
 
 async function connectMongoDb() {
   // Build the connection string
@@ -15,7 +16,7 @@ async function connectMongoDb() {
     socketTimeoutMS: 45000, // Close sockets after 45 seconds of inactivity
   };
 
-  logger.info('[DATABASE] MongoDB - Connecting to ' + dbURI);
+  logger.info(`connectMongoDb - Connecting to ${dbURI}`);
 
   function setRunValidators(this: any) {
     this.setOptions({ runValidators: true });
@@ -33,34 +34,34 @@ async function connectMongoDb() {
     })
     .connect(dbURI, options)
     .then(() => {
-      logger.info('[DATABASE] Mongoose connection done');
+      logger.info('connectMongoDb - Connection successful');
     })
     .catch((e) => {
-      logger.error('[DATABASE] Mongoose connection error');
+      logger.error('connectMongoDb - Connection error');
       logger.error(e);
     });
 
   // CONNECTION EVENTS
   // When successfully connected
   mongoose.connection.on('connected', () => {
-    logger.debug('[DATABASE] Mongoose default connection open to ' + dbURI);
+    logger.debug(`Connection opened to ${dbURI}`);
   });
 
   // If the connection throws an error
   mongoose.connection.on('error', (err) => {
-    logger.error('[DATABASE] Mongoose default connection error: ' + err);
+    logger.error('Connection error: ' + err);
   });
 
   // When the connection is disconnected
   mongoose.connection.on('disconnected', () => {
-    logger.info('[DATABASE] Mongoose default connection disconnected');
+    logger.info('Connection disconnected');
   });
 
   // If the Node process ends, close the Mongoose connection
   process.on('SIGINT', () => {
     // @ts-ignore
     mongoose.connection.close(() => {
-      logger.info('[DATABASE] Mongoose default connection disconnected through app termination');
+      logger.info('Connection disconnected through app termination');
       process.exit(0);
     });
   });

server/src/helpers/query/FilterHelper.ts

@@ -1,7 +1,4 @@
 // Filtering logic
-
-import logger from '../../logger';
-
 export function filterByFields<T>(data: T[], params: any): T[] {
   if (params.filter) {
     const filter = JSON.parse(params.filter as any) as {

server/src/index.ts

@@ -7,7 +7,16 @@ import Crons from './modules/crons';
 import app from './App';
 
 const start = () => {
-  logger.info(`Starting server...`);
+  logger.info(`
+      ,;;:;,
+   ;;;;;
+  ,:;;:;    ,'=.
+  ;:;:;' .=" ,'_\\
+  ':;:;,/  ,__:=@
+   ';;:;  =./)_
+     \`"=\\_  )_"\`
+          \`\`'"\`
+Starting Squirrel Servers Manager server...`);
   connection().then(async () => {
     await Startup.init();
     app.setupRoutes();

server/src/logger.ts

@@ -34,17 +34,17 @@ export const httpLoggerOptions = {
   },
   // Define a custom success message
   customSuccessMessage: function (req, res) {
-    return `${req.method} completed ${(req as typeof req & { originalUrl: string }).originalUrl}`;
+    return `Request completed: ${req.method} - ${(req as typeof req & { originalUrl: string }).originalUrl}`;
   },
 
   // Define a custom receive message
   customReceivedMessage: function (req, res) {
-    return `request received: ${req.method} - ${req.url}`;
+    return `Request received: ${req.method} - ${req.url}`;
   },
 
   // Define a custom error message
   customErrorMessage: function (req, res, err) {
-    return 'request errored with status code: ' + res.statusCode;
+    return `Request errored with status code: ${res.statusCode}`;
   },
 };
 

server/src/modules/ansible/extravars/ExtraVars.ts

@@ -26,7 +26,7 @@ class ExtraVars {
       if (!value && !emptySubstitute) {
         this.logger.error(`findValueOfExtraVars - ExtraVar not found : ${e.extraVar}`);
         if (e.required) {
-          throw new Error('ExtraVar value not found !');
+          throw new Error(`ExtraVar value not found ! (${e.extraVar})`);
         }
       } else {
         substitutedExtraVars.push({ ...e, value: value || undefined });
@@ -62,22 +62,22 @@ class ExtraVars {
 
   private getForcedValue(extraVar: API.ExtraVar, forcedValues?: API.ExtraVars) {
     const forcedValue = forcedValues?.find((e) => e.extraVar === extraVar.extraVar)?.value;
-    this.logger.debug(`forcedValue found ${forcedValue}`);
+    this.logger.debug(`forcedValue found: ${forcedValue}`);
     return forcedValue;
   }
 
   private async getContextExtraVarValue(extraVar: API.ExtraVar, targets?: string[]) {
-    this.logger.debug(`getContextExtraVarValue '${extraVar.extraVar}'`);
+    this.logger.debug(`getContextExtraVarValue - '${extraVar.extraVar}'`);
     if (!targets) {
       return;
     }
     if (targets.length > 1) {
-      throw new Error('Cannot use CONTEXT variable with multiple targets');
+      throw new Error(`Cannot use CONTEXT variable with multiple targets - '${extraVar.extraVar}'`);
     }
     const device = await DeviceRepo.findOneByUuid(targets[0]);
     const user = await UserRepo.findFirst();
     if (!device) {
-      throw new Error('Targeted device not found');
+      throw new Error(`Targeted device not found - (device: ${targets?.[0]})`);
     }
     switch (extraVar.extraVar) {
       case SsmAnsible.DefaultContextExtraVarsList.DEVICE_ID:

server/src/modules/automations/AutomationComponent.ts

@@ -25,7 +25,7 @@ class AutomationComponent {
         moduleId: `${this.uuid}`,
         moduleName: `${name}`,
       },
-      { msgPrefix: '[AUTOMATION-COMPONENT] - ' },
+      { msgPrefix: '[AUTOMATION] - ' },
     );
     this.automationChain = automationChain;
     this.actions = [];
@@ -70,14 +70,14 @@ class AutomationComponent {
   }
 
   async onTrigger() {
-    this.childLogger.info('Triggered');
+    this.childLogger.info(`Automation "${this.name}" triggered...`);
     await this.synchronousExecution();
   }
 
   async synchronousExecution() {
     if (this.actions) {
       for (const action of this.actions) {
-        this.childLogger.info(`Execution a ${action.type} action`);
+        this.childLogger.info(`Executing a ${action.type} action...`);
         await action.executeAction();
       }
     } else {

server/src/modules/automations/actions/AbstractActionComponent.ts

@@ -24,7 +24,7 @@ abstract class AbstractActionComponent extends EventManager {
         moduleName: `${automationName}`,
         type: type,
       },
-      { msgPrefix: '[ACTION-COMPONENT] - ' },
+      { msgPrefix: '[AUTOMATION_ACTION] - ' },
     );
   }
 

server/src/modules/automations/actions/DockerActionComponent.ts

@@ -22,13 +22,13 @@ class DockerActionComponent extends AbstractActionComponent {
   }
 
   async executeAction() {
-    this.childLogger.info('Docker Action Component execute - started');
+    this.childLogger.info('Docker Action Component - executeAction - started');
     let success = true;
     for (const containerId of this.containerIds) {
-      this.childLogger.info(`Docker Action Component execute - ${containerId}`);
+      this.childLogger.info(`Docker Action Component - executeAction for: ${containerId}`);
       const container = await ContainerRepo.findContainerById(containerId);
       if (!container) {
-        this.childLogger.error(`Container not found for ${containerId}`);
+        this.childLogger.error(`Docker Volume Action - Container not found for ${containerId}`);
         success = false;
       } else {
         try {
@@ -39,7 +39,9 @@ class DockerActionComponent extends AbstractActionComponent {
         }
       }
     }
-    this.childLogger.info('Docker Action Component execute - ended');
+    this.childLogger.info(
+      `Docker Action Component - executeAction - ended with ${success ? 'success' : 'failure'}`,
+    );
     if (success) {
       await this.onSuccess();
     } else {

server/src/modules/automations/actions/DockerVolumeActionComponent.ts

@@ -22,10 +22,12 @@ class DockerVolumeActionComponent extends AbstractActionComponent {
   }
 
   async executeAction() {
-    this.childLogger.info('Docker Volume Action Component execute - started');
+    this.childLogger.info(
+      `Docker Volume Action - executeAction (${this.dockerVolumeAction}) - started...`,
+    );
     let success = true;
     for (const volumeUuid of this.volumeUuids) {
-      this.childLogger.info(`Docker Volume Action Component execute - ${volumeUuid}`);
+      this.childLogger.info(`Docker Volume Action - executeAction - for volume: ${volumeUuid}`);
       const volume = await ContainerVolumeRepo.findByUuid(volumeUuid);
       if (!volume) {
         this.childLogger.error(`Volume not found for ${volumeUuid}`);
@@ -45,7 +47,9 @@ class DockerVolumeActionComponent extends AbstractActionComponent {
         }
       }
     }
-    this.childLogger.info('Docker Volume Action Component execute - ended');
+    this.childLogger.info(
+      `Docker Volume Action - executeAction - ${this.dockerVolumeAction} ended with ${success ? 'success' : 'failure'}`,
+    );
     if (success) {
       await this.onSuccess();
     } else {

server/src/modules/automations/actions/PlaybookActionComponent.ts

@@ -28,11 +28,13 @@ class PlaybookActionComponent extends AbstractActionComponent {
   }
 
   async executeAction() {
-    this.childLogger.info('Playbook Action Component execute - started');
+    this.childLogger.info('Playbook Action Component - executeAction - started');
     const user = (await UserRepo.findFirst()) as User;
     const playbook = await PlaybookRepo.findOneByUuid(this.playbookUuid);
     if (!playbook) {
-      this.childLogger.error(`Playbook ${this.playbookUuid} does not exist`);
+      this.childLogger.error(
+        `Playbook Action Component - Playbook ${this.playbookUuid} does not exist`,
+      );
       return;
     }
     try {
@@ -60,7 +62,9 @@ class PlaybookActionComponent extends AbstractActionComponent {
   };
 
   async waitForResult(execId: string, timeoutCount = 0) {
-    this.childLogger.info(`wait for result ${execId} - (try: ${timeoutCount}/100)`);
+    this.childLogger.info(
+      `Playbook Action Component - wait for result ${execId} - (try: ${timeoutCount}/100)`,
+    );
     try {
       if (timeoutCount > 100) {
         this.childLogger.error('Timeout reached for task');
@@ -69,13 +73,17 @@ class PlaybookActionComponent extends AbstractActionComponent {
       }
       const execStatuses = await AnsibleTaskStatusRepo.findAllByIdent(execId);
       if (!execStatuses || execStatuses.length === 0) {
-        this.childLogger.warn(`No execution statuses found (yet) for execId: ${execId}`);
+        this.childLogger.warn(
+          `Playbook Action Component - No execution statuses found (yet) for execId: ${execId}`,
+        );
         setTimeout(() => {
           this.waitForResult(execId, timeoutCount + 1);
         }, 5000);
       } else {
         const lastExecStatus = execStatuses[0];
-        this.childLogger.info(`Latest execution status ${lastExecStatus.status}`);
+        this.childLogger.info(
+          `Playbook Action Component - Latest execution status ${lastExecStatus.status}`,
+        );
         if (PlaybookActionComponent.isFinalStatus(lastExecStatus.status as string)) {
           if (lastExecStatus.status === SsmAnsible.AnsibleTaskStatus.SUCCESS) {
             await this.onSuccess();
@@ -99,7 +107,10 @@ class PlaybookActionComponent extends AbstractActionComponent {
     try {
       await this.onError();
     } catch (innerError) {
-      this.childLogger.error('Error during onError handling:', innerError);
+      this.childLogger.error(
+        'Playbook Action Component - Error during onError handling:',
+        innerError,
+      );
     }
   }
 }

server/src/modules/docker/core/Component.ts

@@ -62,7 +62,7 @@ abstract class Component<
       { msgPrefix: `[${kind.toUpperCase()}][${type.toUpperCase()}] - ` },
     );
     this.childLogger.info(
-      `Register with configuration ${JSON.stringify(this.maskConfiguration())}`,
+      `Registering ${this.kind?.toLowerCase()} with configuration: ${JSON.stringify(this.maskConfiguration())}`,
     );
     await this.init();
     return this;