chore(logs): improve mongo and graphql logs (#555)

* chore(logs): improve mongo and graphql logs

* beautify logs

* Bump version up to 1.2.5

* rm utils

* improve grapgql log

* improve mongo logs

* Update logger.ts

---------

Co-authored-by: github-actions <41898282+github-actions[bot]@users.noreply.github.com>

Author: neSpecc

package.json

@@ -1,6 +1,6 @@
 {
   "name": "hawk.api",
-  "version": "1.2.4",
+  "version": "1.2.5",
   "main": "index.ts",
   "license": "BUSL-1.1",
   "scripts": {

src/index.ts

@@ -26,8 +26,8 @@ import PlansFactory from './models/plansFactory';
 import BusinessOperationsFactory from './models/businessOperationsFactory';
 import schema from './schema';
 import { graphqlUploadExpress } from 'graphql-upload';
-import morgan from 'morgan';
 import { metricsMiddleware, createMetricsServer, graphqlMetricsPlugin } from './metrics';
+import { requestLogger } from './utils/logger';
 
 /**
  * Option to enable playground
@@ -85,19 +85,17 @@ class HawkAPI {
       next();
     });
 
-    /**
-     * Setup request logger.
-     * Uses 'combined' format in production for Apache-style logging,
-     * and 'dev' format in development for colored, concise output.
-     */
-    this.app.use(morgan(process.env.NODE_ENV === 'production' ? 'combined' : 'dev'));
-
     /**
      * Add metrics middleware to track HTTP requests
      */
     this.app.use(metricsMiddleware);
 
     this.app.use(express.json());
+
+    /**
+     * Setup request logger with custom formatters (GraphQL operation name support)
+     */
+    this.app.use(requestLogger);
     this.app.use(bodyParser.urlencoded({ extended: false }));
     this.app.use('/static', express.static(`./static`));
 

src/metrics/mongodb.ts

@@ -1,5 +1,6 @@
 import promClient from 'prom-client';
 import { MongoClient, MongoClientOptions } from 'mongodb';
+import { Effect, sgr } from '../utils/ansi';
 
 /**
  * MongoDB command duration histogram
@@ -113,12 +114,155 @@ export function withMongoMetrics(options: MongoClientOptions = {}): MongoClientO
   };
 }
 
+/**
+ * Format filter/update parameters for logging
+ * @param params - Parameters to format
+ * @returns Formatted string
+ */
+function formatParams(params: any): string {
+  if (!params || Object.keys(params).length === 0) {
+    return '';
+  }
+
+  try {
+    return JSON.stringify(params);
+  } catch (e) {
+    return String(params);
+  }
+}
+
+/**
+ * Colorize duration based on performance thresholds
+ * @param duration - Duration in milliseconds
+ * @returns Colorized duration string
+ */
+function colorizeDuration(duration: number): string {
+  let color: Effect;
+
+  if (duration < 50) {
+    color = Effect.ForegroundGreen;
+  } else if (duration < 100) {
+    color = Effect.ForegroundYellow;
+  } else {
+    color = Effect.ForegroundRed;
+  }
+
+  return sgr(`${duration}ms`, color);
+}
+
+/**
+ * Interface for storing command information with timestamp
+ */
+interface StoredCommandInfo {
+  formattedCommand: string;
+  timestamp: number;
+}
+
+/**
+ * Map to store formatted command information by requestId
+ */
+const commandInfoMap = new Map<number, StoredCommandInfo>();
+
+/**
+ * Timeout for cleaning up stale command info (30 seconds)
+ */
+const COMMAND_INFO_TIMEOUT_MS = 30000;
+
+/**
+ * Cleanup stale command info to prevent memory leaks
+ * Removes entries older than COMMAND_INFO_TIMEOUT_MS
+ */
+function cleanupStaleCommandInfo(): void {
+  const now = Date.now();
+  const keysToDelete: number[] = [];
+
+  for (const [requestId, info] of commandInfoMap.entries()) {
+    if (now - info.timestamp > COMMAND_INFO_TIMEOUT_MS) {
+      keysToDelete.push(requestId);
+    }
+  }
+
+  if (keysToDelete.length > 0) {
+    console.warn(`Cleaning up ${keysToDelete.length} stale MongoDB command info entries (possible memory leak)`);
+    for (const key of keysToDelete) {
+      commandInfoMap.delete(key);
+    }
+  }
+}
+
+/**
+ * Periodic cleanup interval
+ */
+setInterval(cleanupStaleCommandInfo, COMMAND_INFO_TIMEOUT_MS);
+
+/**
+ * Store MongoDB command details for later logging
+ * @param event - MongoDB command event
+ */
+function storeCommandInfo(event: any): void {
+  const collectionRaw = extractCollectionFromCommand(event.command, event.commandName);
+  const collection = sgr(normalizeCollectionName(collectionRaw), Effect.ForegroundGreen);
+  const db = event.databaseName || 'unknown db';
+  const commandName = sgr(event.commandName, Effect.ForegroundRed);
+  const filter = event.command.filter;
+  const update = event.command.update;
+  const pipeline = event.command.pipeline;
+  const projection = event.command.projection;
+  const params = filter || update || pipeline;
+  const paramsStr = formatParams(params);
+  const projectionStr = projection ? ` projection: ${formatParams(projection)}` : '';
+
+  const formattedCommand = `[${event.requestId}] ${db}.${collection}.${commandName}(${paramsStr})${projectionStr}`;
+
+  commandInfoMap.set(event.requestId, {
+    formattedCommand,
+    timestamp: Date.now(),
+  });
+}
+
+/**
+ * Log MongoDB command success to console
+ * Format: [requestId] db.collection.command(params) ✓ duration
+ * @param event - MongoDB command event
+ */
+function logCommandSucceeded(event: any): void {
+  const info = commandInfoMap.get(event.requestId);
+  const durationStr = colorizeDuration(event.duration);
+
+  if (info) {
+    console.log(`${info.formattedCommand} ✓ ${durationStr}`);
+    commandInfoMap.delete(event.requestId);
+  } else {
+    console.log(`[${event.requestId}] ${event.commandName} ✓ ${durationStr}`);
+  }
+}
+
+/**
+ * Log MongoDB command failure to console
+ * Format: [requestId] db.collection.command(params) ✗ error duration
+ * @param event - MongoDB command event
+ */
+function logCommandFailed(event: any): void {
+  const errorMsg = event.failure?.message || event.failure?.errmsg || 'Unknown error';
+  const info = commandInfoMap.get(event.requestId);
+  const durationStr = colorizeDuration(event.duration);
+
+  if (info) {
+    console.error(`${info.formattedCommand} ✗ ${errorMsg} ${durationStr}`);
+    commandInfoMap.delete(event.requestId);
+  } else {
+    console.error(`[${event.requestId}] ${event.commandName} ✗ ${errorMsg} ${durationStr}`);
+  }
+}
+
 /**
  * Setup MongoDB metrics monitoring on a MongoClient
  * @param client - MongoDB client to monitor
  */
 export function setupMongoMetrics(client: MongoClient): void {
   client.on('commandStarted', (event) => {
+    storeCommandInfo(event);
+
     // Store start time and metadata for this command
     const metadataKey = `${event.requestId}`;
 
@@ -139,6 +283,8 @@ export function setupMongoMetrics(client: MongoClient): void {
   });
 
   client.on('commandSucceeded', (event) => {
+    logCommandSucceeded(event);
+
     const metadataKey = `${event.requestId}`;
     // eslint-disable-next-line @typescript-eslint/no-explicit-any
     const metadata = (client as any)[metadataKey];
@@ -157,6 +303,8 @@ export function setupMongoMetrics(client: MongoClient): void {
   });
 
   client.on('commandFailed', (event) => {
+    logCommandFailed(event);
+
     const metadataKey = `${event.requestId}`;
     // eslint-disable-next-line @typescript-eslint/no-explicit-any
     const metadata = (client as any)[metadataKey];

src/models/eventsFactory.js

@@ -665,7 +665,7 @@ class EventsFactory extends Factory {
   async getEventRelease(eventId) {
     const eventOriginal = await this.findById(eventId);
 
-    if (!eventOriginal) {
+    if (!eventOriginal || !eventOriginal.payload.release) {
       return null;
     }
 

src/mongo.ts

@@ -75,7 +75,9 @@ export async function setupConnections(): Promise<void> {
     databases.hawk = hawkMongoClient.db();
     databases.events = eventsMongoClient.db();
 
-    // Setup metrics monitoring for both clients
+    /**
+     * Log and and measure MongoDB metrics
+     */
     setupMongoMetrics(hawkMongoClient);
     setupMongoMetrics(eventsMongoClient);
   } catch (e) {

src/utils/ansi.ts

@@ -0,0 +1,44 @@
+/**
+ * ANSI escape codes for text formatting
+ */
+export enum Effect {
+  Reset = '\x1b[0m',
+  Bold = '\x1b[1m',
+  Underline = '\x1b[4m',
+  CrossedOut = '\x1b[9m',
+  BoldOff = '\x1b[22m',
+  UnderlineOff = '\x1b[24m',
+  CrossedOutOff = '\x1b[29m',
+  ForegroundRed = '\x1b[31m',
+  ForegroundGreen = '\x1b[32m',
+  ForegroundYellow = '\x1b[33m',
+  ForegroundBlue = '\x1b[34m',
+  ForegroundMagenta = '\x1b[35m',
+  ForegroundCyan = '\x1b[36m',
+  ForegroundWhite = '\x1b[37m',
+  ForegroundGray = '\x1b[90m',
+  BackgroundRed = '\x1b[41m',
+  BackgroundGreen = '\x1b[42m',
+  BackgroundYellow = '\x1b[43m',
+  BackgroundBlue = '\x1b[44m',
+  BackgroundMagenta = '\x1b[45m',
+  BackgroundCyan = '\x1b[46m',
+  BackgroundWhite = '\x1b[47m',
+  BackgroundGray = '\x1b[100m',
+};
+
+/**
+ * ANSI escape code for setting visual effects using SGR (Select Graphic Rendition) subset
+ *
+ * @example console.log('Hello, ${sgr('world', Effect.ForegroundRed)}');
+ *
+ *
+ * @param message - The message to colorize
+ * @param color - The color to apply
+ * @returns The colored message
+ */
+export function sgr(message: string, color: Effect | Effect[]): string {
+  const colorCode = Array.isArray(color) ? color.join('') : color ?? Effect.Reset;
+
+  return `${colorCode}${message}${Effect.Reset}`;
+}

src/utils/logger.ts

@@ -0,0 +1,41 @@
+import morgan from 'morgan';
+import express from 'express';
+import { sgr, Effect } from './ansi';
+
+/**
+ * Setup custom GraphQL-aware morgan token.
+ * Extracts operation name from GraphQL requests to show query/mutation names in logs.
+ */
+morgan.token('graphql-operation', (req: express.Request) => {
+  if (req.body && req.body.operationName) {
+    return req.body.operationName;
+  }
+  if (req.body && req.body.query) {
+    /* Try to extract operation name from query string if operationName is not provided */
+    const match = req.body.query.match(/(?:query|mutation)\s+(\w+)/);
+    const isMutation = req.body.query.includes('mutation');
+
+    const effect = isMutation ? Effect.ForegroundRed : Effect.ForegroundMagenta;
+    const prefix = sgr(isMutation ? 'mutation' : 'query', effect);
+
+    if (match && match[1]) {
+      return prefix + ' ' + sgr(sgr(match[1], effect), Effect.Bold);
+    }
+  }
+
+  return '-';
+});
+
+/**
+ * Custom morgan format for GraphQL-aware logging.
+ * Development: shows method, url, operation name, status, response time, content length
+ * Production: Apache-style format with operation name included
+ */
+const customFormat = process.env.NODE_ENV === 'production'
+  ? ':remote-addr - :remote-user [:date[clf]] ":method :url :graphql-operation" :status :res[content-length] bytes - :response-time ms'
+  : ':method :url :graphql-operation :status :res[content-length] bytes - :response-time ms';
+
+/**
+ * Configured morgan middleware with GraphQL operation name logging
+ */
+export const requestLogger = morgan(customFormat);