refactor(api): Central Logging 📜 (#1348)

* WIP: initial logging changes
add several transports in ~/config/winston
omit messages in logs, truncate long strings
add short blurb in dotenv for debug logging
GoogleClient: using logger
OpenAIClient: using logger, handleOpenAIErrors
Adding typedef for payload message
bumped winston and using winston-daily-rotate-file
moved config for server paths to ~/config dir
Added `DEBUG_LOGGING=true` to .env.example

* WIP: Refactor logging statements in code

* WIP: Refactor logging statements and import configurations

* WIP: Refactor logging statements and import configurations

* refactor: broadcast Redis initialization message with `info` not `debug`

* refactor: complete Refactor logging statements and import configurations

* chore: delete unused tools

* fix: circular dependencies due to accessing logger

* refactor(handleText): handle booleans and write tests

* refactor: redact sensitive values, better formatting

* chore: improve log formatting, avoid passing strings to 2nd arg

* fix(ci): fix jest tests due to logger changes

* refactor(getAvailablePluginsController): cache plugins as they are static and avoids async addOpenAPISpecs call every time

* chore: update docs

* chore: update docs

* chore: create separate meiliSync logger, clean up logs to avoid being unnecessarily verbose

* chore: spread objects where they are commonly logged to allow string truncation

* chore: improve error log formatting

api/config/index.js

@@ -0,0 +1,5 @@
+const logger = require('./winston');
+
+module.exports = {
+  logger,
+};

api/config/meiliLogger.js

@@ -0,0 +1,78 @@
+const path = require('path');
+const winston = require('winston');
+require('winston-daily-rotate-file');
+
+const logDir = path.join(__dirname, '..', 'logs');
+
+const { NODE_ENV } = process.env;
+
+const levels = {
+  error: 0,
+  warn: 1,
+  info: 2,
+  http: 3,
+  verbose: 4,
+  debug: 5,
+  activity: 6,
+  silly: 7,
+};
+
+winston.addColors({
+  info: 'green', // fontStyle color
+  warn: 'italic yellow',
+  error: 'red',
+  debug: 'blue',
+});
+
+const level = () => {
+  const env = NODE_ENV || 'development';
+  const isDevelopment = env === 'development';
+  return isDevelopment ? 'debug' : 'warn';
+};
+
+const fileFormat = winston.format.combine(
+  winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
+  winston.format.errors({ stack: true }),
+  winston.format.splat(),
+);
+
+const transports = [
+  new winston.transports.DailyRotateFile({
+    level: 'debug',
+    filename: `${logDir}/meiliSync-%DATE%.log`,
+    datePattern: 'YYYY-MM-DD',
+    zippedArchive: true,
+    maxSize: '20m',
+    maxFiles: '14d',
+    format: fileFormat,
+  }),
+];
+
+// if (NODE_ENV !== 'production') {
+//   transports.push(
+//     new winston.transports.Console({
+//       format: winston.format.combine(winston.format.colorize(), winston.format.simple()),
+//     }),
+//   );
+// }
+
+const consoleFormat = winston.format.combine(
+  winston.format.colorize({ all: true }),
+  winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
+  winston.format.printf((info) => `${info.timestamp} ${info.level}: ${info.message}`),
+);
+
+transports.push(
+  new winston.transports.Console({
+    level: 'info',
+    format: consoleFormat,
+  }),
+);
+
+const logger = winston.createLogger({
+  level: level(),
+  levels,
+  transports,
+});
+
+module.exports = logger;

api/config/parsers.js

@@ -0,0 +1,128 @@
+const util = require('util');
+const winston = require('winston');
+const traverse = require('traverse');
+const { klona } = require('klona/full');
+
+const sensitiveKeys = [/^sk-\w+$/];
+
+/**
+ * Determines if a given key string is sensitive.
+ *
+ * @param {string} keyStr - The key string to check.
+ * @returns {boolean} True if the key string matches known sensitive key patterns.
+ */
+function isSensitiveKey(keyStr) {
+  if (keyStr) {
+    return sensitiveKeys.some((regex) => regex.test(keyStr));
+  }
+  return false;
+}
+
+/**
+ * Recursively redacts sensitive information from an object.
+ *
+ * @param {object} obj - The object to traverse and redact.
+ */
+function redactObject(obj) {
+  traverse(obj).forEach(function redactor() {
+    if (isSensitiveKey(this.key)) {
+      this.update('[REDACTED]');
+    }
+  });
+}
+
+/**
+ * Deep copies and redacts sensitive information from an object.
+ *
+ * @param {object} obj - The object to copy and redact.
+ * @returns {object} The redacted copy of the original object.
+ */
+function redact(obj) {
+  const copy = klona(obj); // Making a deep copy to prevent side effects
+  redactObject(copy);
+
+  const splat = copy[Symbol.for('splat')];
+  redactObject(splat); // Specifically redact splat Symbol
+
+  return copy;
+}
+
+/**
+ * Truncates long strings, especially base64 image data, within log messages.
+ *
+ * @param {any} value - The value to be inspected and potentially truncated.
+ * @returns {any} - The truncated or original value.
+ */
+const truncateLongStrings = (value) => {
+  if (typeof value === 'string') {
+    return value.length > 100 ? value.substring(0, 100) + '... [truncated]' : value;
+  }
+
+  return value;
+};
+
+// /**
+//  * Processes each message in the messages array, specifically looking for and truncating
+//  * base64 image URLs in the content. If a base64 image URL is found, it replaces the URL
+//  * with a truncated message.
+//  *
+//  * @param {PayloadMessage} message - The payload message object to format.
+//  * @returns {PayloadMessage} - The processed message object with base64 image URLs truncated.
+//  */
+// const truncateBase64ImageURLs = (message) => {
+//   // Create a deep copy of the message
+//   const messageCopy = JSON.parse(JSON.stringify(message));
+
+//   if (messageCopy.content && Array.isArray(messageCopy.content)) {
+//     messageCopy.content = messageCopy.content.map(contentItem => {
+//       if (contentItem.type === 'image_url' && contentItem.image_url && isBase64String(contentItem.image_url.url)) {
+//         return { ...contentItem, image_url: { ...contentItem.image_url, url: 'Base64 Image Data... [truncated]' } };
+//       }
+//       return contentItem;
+//     });
+//   }
+//   return messageCopy;
+// };
+
+// /**
+//  * Checks if a string is a base64 image data string.
+//  *
+//  * @param {string} str - The string to be checked.
+//  * @returns {boolean} - True if the string is base64 image data, otherwise false.
+//  */
+// const isBase64String = (str) => /^data:image\/[a-zA-Z]+;base64,/.test(str);
+
+/**
+ * Custom log format for Winston that handles deep object inspection.
+ * It specifically truncates long strings and handles nested structures within metadata.
+ *
+ * @param {Object} info - Information about the log entry.
+ * @returns {string} - The formatted log message.
+ */
+const deepObjectFormat = winston.format.printf(({ level, message, timestamp, ...metadata }) => {
+  let msg = `${timestamp} ${level}: ${message}`;
+
+  if (Object.keys(metadata).length) {
+    Object.entries(metadata).forEach(([key, value]) => {
+      let val = value;
+      if (key === 'modelOptions' && value && Array.isArray(value.messages)) {
+        // Create a shallow copy of the messages array
+        // val = { ...value, messages: value.messages.map(truncateBase64ImageURLs) };
+        val = { ...value, messages: `${value.messages.length} message(s) in payload` };
+      }
+      // Inspects each metadata value; applies special handling for 'messages'
+      const inspectedValue =
+        typeof val === 'string'
+          ? truncateLongStrings(val)
+          : util.inspect(val, { depth: null, colors: false }); // Use 'val' here
+      msg += ` ${key}: ${inspectedValue}`;
+    });
+  }
+
+  return msg;
+});
+
+module.exports = {
+  redact,
+  deepObjectFormat,
+};

api/config/paths.js

@@ -0,0 +1,6 @@
+const path = require('path');
+
+module.exports = {
+  publicPath: path.resolve(__dirname, '..', '..', 'client', 'public'),
+  imageOutput: path.resolve(__dirname, '..', '..', 'client', 'public', 'images'),
+};

api/config/winston.js

@@ -0,0 +1,113 @@
+const path = require('path');
+const winston = require('winston');
+require('winston-daily-rotate-file');
+const { redact, deepObjectFormat } = require('./parsers');
+const { isEnabled } = require('~/server/utils/handleText');
+
+const logDir = path.join(__dirname, '..', 'logs');
+
+const { NODE_ENV, DEBUG_LOGGING = true, DEBUG_CONSOLE = false } = process.env;
+
+const levels = {
+  error: 0,
+  warn: 1,
+  info: 2,
+  http: 3,
+  verbose: 4,
+  debug: 5,
+  activity: 6,
+  silly: 7,
+};
+
+winston.addColors({
+  info: 'green', // fontStyle color
+  warn: 'italic yellow',
+  error: 'red',
+  debug: 'blue',
+});
+
+const level = () => {
+  const env = NODE_ENV || 'development';
+  const isDevelopment = env === 'development';
+  return isDevelopment ? 'debug' : 'warn';
+};
+
+const fileFormat = winston.format.combine(
+  winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
+  winston.format.errors({ stack: true }),
+  winston.format.splat(),
+  winston.format((info) => redact(info))(),
+);
+
+const transports = [
+  new winston.transports.DailyRotateFile({
+    level: 'error',
+    filename: `${logDir}/error-%DATE%.log`,
+    datePattern: 'YYYY-MM-DD',
+    zippedArchive: true,
+    maxSize: '20m',
+    maxFiles: '14d',
+    format: fileFormat,
+  }),
+  // new winston.transports.DailyRotateFile({
+  //   level: 'info',
+  //   filename: `${logDir}/info-%DATE%.log`,
+  //   datePattern: 'YYYY-MM-DD',
+  //   zippedArchive: true,
+  //   maxSize: '20m',
+  //   maxFiles: '14d',
+  // }),
+];
+
+// if (NODE_ENV !== 'production') {
+//   transports.push(
+//     new winston.transports.Console({
+//       format: winston.format.combine(winston.format.colorize(), winston.format.simple()),
+//     }),
+//   );
+// }
+
+if (isEnabled && isEnabled(DEBUG_LOGGING)) {
+  transports.push(
+    new winston.transports.DailyRotateFile({
+      level: 'debug',
+      filename: `${logDir}/debug-%DATE%.log`,
+      datePattern: 'YYYY-MM-DD',
+      zippedArchive: true,
+      maxSize: '20m',
+      maxFiles: '14d',
+      format: winston.format.combine(fileFormat, deepObjectFormat),
+    }),
+  );
+}
+
+const consoleFormat = winston.format.combine(
+  winston.format.colorize({ all: true }),
+  winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
+  winston.format((info) => redact(info))(),
+  winston.format.printf((info) => `${info.timestamp} ${info.level}: ${info.message}`),
+);
+
+if (isEnabled && isEnabled(DEBUG_CONSOLE)) {
+  transports.push(
+    new winston.transports.Console({
+      level: 'debug',
+      format: winston.format.combine(consoleFormat, deepObjectFormat),
+    }),
+  );
+} else {
+  transports.push(
+    new winston.transports.Console({
+      level: 'info',
+      format: consoleFormat,
+    }),
+  );
+}
+
+const logger = winston.createLogger({
+  level: level(),
+  levels,
+  transports,
+});
+
+module.exports = logger;