chore(logger): improve format (#3290)

* chore(logger): improve format

* fix: build

* feat: develop format

* chore: develop -> console

packages/core/app/src/config/logger.ts

@@ -1,4 +1,5 @@
-import { AppLoggerOptions, getLoggerLevel, getLoggerTransport } from '@nocobase/logger';
+import { getLoggerLevel, getLoggerTransport } from '@nocobase/logger';
+import { AppLoggerOptions } from '@nocobase/server';
 
 export default {
   request: {

packages/core/logger/src/app-logger.ts

@@ -1,23 +0,0 @@
-import { Logger } from 'winston';
-import { SystemLoggerOptions, createSystemLogger } from './system-logger';
-import { getLoggerFilePath } from './config';
-
-export const createAppLogger = ({ app, ...options }: SystemLoggerOptions & { app?: string }) =>
-  createSystemLogger({ dirname: getLoggerFilePath(app), filename: 'system', seperateError: true, ...options });
-
-export type logMethod = (
-  message: string,
-  meta?: {
-    module?: string;
-    submodule?: string;
-    method?: string;
-    [key: string]: any;
-  },
-) => AppLogger;
-
-export interface AppLogger extends Omit<Logger, 'info' | 'warn' | 'error' | 'debug'> {
-  info: logMethod;
-  warn: logMethod;
-  error: logMethod;
-  debug: logMethod;
-}

packages/core/logger/src/config.ts

@@ -13,5 +13,5 @@ export const getLoggerTransport = (): ('console' | 'file' | 'dailyRotateFile')[]
     (process.env.APP_ENV === 'development' ? 'console' : 'console,dailyRotateFile')
   ).split(',');
 
-export const getLoggerFormat = (): 'logfmt' | 'json' | 'delimiter' =>
-  (process.env.LOGGER_FORMAT as any) || (process.env.APP_ENV === 'development' ? 'logfmt' : 'json');
+export const getLoggerFormat = (): 'logfmt' | 'json' | 'delimiter' | 'console' =>
+  (process.env.LOGGER_FORMAT as any) || (process.env.APP_ENV === 'development' ? 'console' : 'json');

packages/core/logger/src/format.ts

@@ -2,20 +2,19 @@ import chalk from 'chalk';
 import winston from 'winston';
 import { getLoggerFormat } from './config';
 import { LoggerOptions } from './logger';
+import { isEmpty } from 'lodash';
 
 const DEFAULT_DELIMITER = '|';
 
-const colorize = {
-  errors: chalk.red,
-  module: chalk.cyan,
-  reqId: chalk.gray,
-  request: chalk.green,
-};
+const colorize = {};
 
 export const getFormat = (format?: LoggerOptions['format']) => {
   const configFormat = format || getLoggerFormat();
   let logFormat: winston.Logform.Format;
   switch (configFormat) {
+    case 'console':
+      logFormat = winston.format.combine(consoleFormat);
+      break;
     case 'logfmt':
       logFormat = logfmtFormat;
       break;
@@ -23,7 +22,7 @@ export const getFormat = (format?: LoggerOptions['format']) => {
       logFormat = winston.format.combine(escapeFormat, delimiterFormat);
       break;
     case 'json':
-      logFormat = winston.format.combine(stripColorFormat, winston.format.json({ deterministic: false }));
+      logFormat = winston.format.combine(winston.format.json({ deterministic: false }));
       break;
     default:
       return winston.format.combine(format as winston.Logform.Format);
@@ -33,17 +32,14 @@ export const getFormat = (format?: LoggerOptions['format']) => {
 
 export const colorFormat: winston.Logform.Format = winston.format((info) => {
   Object.entries(info).forEach(([k, v]) => {
-    if (k === 'message' && info['level'].includes('error')) {
-      info[k] = colorize.errors(v);
+    const level = info['level'];
+    if (colorize[k]) {
+      info[k] = colorize[k](v);
+      return;
     }
-    if (k === 'reqId' && v) {
-      info[k] = colorize.reqId(v);
-    }
-    if ((k === 'module' || k === 'submodule') && v) {
-      info[k] = colorize.module(v);
-    }
-    if (v === 'request' || v === 'response') {
-      info[k] = colorize.request(v);
+    if (colorize[level]?.[k]) {
+      info[k] = colorize[level][k](v);
+      return;
     }
   });
   return info;
@@ -79,6 +75,45 @@ export const logfmtFormat: winston.Logform.Format = winston.format.printf((info)
     .join(' '),
 );
 
+export const consoleFormat: winston.Logform.Format = winston.format.printf((info) => {
+  const keys = ['level', 'timestamp', 'message'];
+  Object.entries(info).forEach(([k, v]) => {
+    if (typeof v === 'object') {
+      if (isEmpty(v)) {
+        info[k] = '';
+        return;
+      }
+      try {
+        info[k] = JSON.stringify(v);
+      } catch (error) {
+        info[k] = String(v);
+      }
+    }
+    if (v === undefined || v === null) {
+      info[k] = '';
+    }
+  });
+
+  const tags = Object.entries(info)
+    .filter(([k, v]) => !keys.includes(k) && v)
+    .map(([k, v]) => `${k}=${v}`)
+    .join(' ');
+
+  const level = info.level.padEnd(5, ' ');
+  const message = info.message.padEnd(44, ' ');
+  const color =
+    {
+      error: chalk.red,
+      warn: chalk.yellow,
+      info: chalk.green,
+      debug: chalk.blue,
+    }[info.level] || chalk.white;
+  const colorized = message.startsWith('Executing')
+    ? color(`${info.timestamp} [${level}]`) + ` ${message}`
+    : color(`${info.timestamp} [${level}] ${message}`);
+  return `${colorized} ${tags}`;
+});
+
 export const delimiterFormat = winston.format.printf((info) =>
   Object.entries(info)
     .map(([, v]) => {
@@ -103,4 +138,4 @@ export const escapeFormat: winston.Logform.Format = winston.format((info) => {
   return { ...info, message };
 })();
 
-export const sortFormat = winston.format((info) => ({ level: info.level, timestamp: info.timestamp, ...info }))();
+export const sortFormat = winston.format((info) => ({ level: info.level, ...info }))();

packages/core/logger/src/index.ts

@@ -2,5 +2,4 @@ export * from './config';
 export * from './logger';
 export * from './system-logger';
 export * from './request-logger';
-export * from './app-logger';
 export * from './transports';

packages/core/logger/src/logger.ts

@@ -1,14 +1,13 @@
 import winston, { Logger } from 'winston';
-import { SystemLoggerOptions } from './system-logger';
 import 'winston-daily-rotate-file';
 import { getLoggerLevel } from './config';
 import { getTransports } from './transports';
-import { colorFormat, logfmtFormat, sortFormat } from './format';
+import { consoleFormat } from './format';
 
 interface LoggerOptions extends Omit<winston.LoggerOptions, 'transports' | 'format'> {
   dirname?: string;
   filename?: string;
-  format?: 'logfmt' | 'json' | 'delimiter' | winston.Logform.Format;
+  format?: 'logfmt' | 'json' | 'delimiter' | 'console' | winston.Logform.Format;
   transports?: ('console' | 'file' | 'dailyRotateFile' | winston.transport)[];
 }
 
@@ -33,7 +32,7 @@ export const createConsoleLogger = (options?: winston.LoggerOptions) => {
       winston.format.timestamp({
         format: 'YYYY-MM-DD HH:mm:ss',
       }),
-      format || winston.format.combine(sortFormat, colorFormat, logfmtFormat),
+      format || consoleFormat,
     ),
     ...(rest || {}),
     transports: [new winston.transports.Console()],
@@ -41,13 +40,3 @@ export const createConsoleLogger = (options?: winston.LoggerOptions) => {
 };
 
 export { Logger, LoggerOptions };
-interface ReqeustLoggerOptions extends LoggerOptions {
-  skip?: (ctx?: any) => Promise<boolean>;
-  requestWhitelist?: string[];
-  responseWhitelist?: string[];
-}
-
-export interface AppLoggerOptions {
-  request: ReqeustLoggerOptions;
-  system: SystemLoggerOptions;
-}

packages/core/logger/src/request-logger.ts

@@ -1,5 +1,5 @@
 import { getLoggerFilePath } from './config';
-import { AppLoggerOptions, createLogger } from './logger';
+import { LoggerOptions, createLogger } from './logger';
 import { pick } from 'lodash';
 const defaultRequestWhitelist = [
   'action',
@@ -11,11 +11,17 @@ const defaultRequestWhitelist = [
 ];
 const defaultResponseWhitelist = ['status'];
 
-export const requestLogger = (appName: string, options?: AppLoggerOptions) => {
+export interface RequestLoggerOptions extends LoggerOptions {
+  skip?: (ctx?: any) => Promise<boolean>;
+  requestWhitelist?: string[];
+  responseWhitelist?: string[];
+}
+
+export const requestLogger = (appName: string, options?: RequestLoggerOptions) => {
   const requestLogger = createLogger({
     dirname: getLoggerFilePath(appName),
     filename: 'request',
-    ...(options?.request || {}),
+    ...(options || {}),
   });
   return async (ctx, next) => {
     const reqId = ctx.reqId;
@@ -29,11 +35,12 @@ export const requestLogger = (appName: string, options?: AppLoggerOptions) => {
       path: ctx.url,
     };
     requestLogger.info({
-      reqId,
       message: 'request',
       ...requestInfo,
-      req: pick(ctx.request.toJSON(), options?.request?.requestWhitelist || defaultRequestWhitelist),
+      req: pick(ctx.request.toJSON(), options?.requestWhitelist || defaultRequestWhitelist),
       action: ctx.action?.toJSON?.(),
+      app: appName,
+      reqId,
     });
     let error: Error;
     try {
@@ -44,14 +51,15 @@ export const requestLogger = (appName: string, options?: AppLoggerOptions) => {
       const cost = Date.now() - startTime;
       const status = ctx.status;
       const info = {
-        reqId,
         message: 'response',
         ...requestInfo,
-        res: pick(ctx.response.toJSON(), options?.request?.responseWhitelist || defaultResponseWhitelist),
+        res: pick(ctx.response.toJSON(), options?.responseWhitelist || defaultResponseWhitelist),
         action: ctx.action?.toJSON?.(),
         userId: ctx.auth?.user?.id,
         status: ctx.status,
         cost,
+        app: appName,
+        reqId,
       };
       if (Math.floor(status / 100) == 5) {
         requestLogger.error({ ...info, res: ctx.body?.['errors'] || ctx.body });

packages/core/logger/src/system-logger.ts

@@ -1,4 +1,4 @@
-import winston, { format } from 'winston';
+import winston, { Logger, format } from 'winston';
 import { LoggerOptions, createLogger } from './logger';
 import Transport from 'winston-transport';
 import { SPLAT } from 'triple-beam';
@@ -8,6 +8,23 @@ export interface SystemLoggerOptions extends LoggerOptions {
   seperateError?: boolean; // print error seperately, default true
 }
 
+export type logMethod = (
+  message: string,
+  meta?: {
+    module?: string;
+    submodule?: string;
+    method?: string;
+    [key: string]: any;
+  },
+) => SystemLogger;
+
+export interface SystemLogger extends Omit<Logger, 'info' | 'warn' | 'error' | 'debug'> {
+  info: logMethod;
+  warn: logMethod;
+  error: logMethod;
+  debug: logMethod;
+}
+
 class SystemLoggerTransport extends Transport {
   private logger: winston.Logger;
   private errorLogger: winston.Logger;
@@ -32,23 +49,24 @@ class SystemLoggerTransport extends Transport {
   }
 
   log(info: any, callback: any) {
-    const { level, message, reqId, [SPLAT]: args } = info;
+    const { level, message, reqId, app, [SPLAT]: args } = info;
     const logger = level === 'error' && this.errorLogger ? this.errorLogger : this.logger;
     const { module, submodule, method, ...meta } = args?.[0] || {};
     logger.log({
       level,
-      reqId,
       message,
+      meta,
       module: module || info['module'] || '',
       submodule: submodule || info['submodule'] || '',
       method: method || '',
-      meta,
+      app,
+      reqId,
     });
     callback(null, true);
   }
 }
 
-export const createSystemLogger = (options: SystemLoggerOptions) =>
+export const createSystemLogger = (options: SystemLoggerOptions): SystemLogger =>
   winston.createLogger({
     transports: [new SystemLoggerTransport(options)],
   });

packages/core/logger/src/transports.ts

@@ -3,7 +3,7 @@ import { DailyRotateFileTransportOptions } from 'winston-daily-rotate-file';
 import { LoggerOptions } from './logger';
 import { getLoggerFilePath, getLoggerFormat, getLoggerTransport } from './config';
 import path from 'path';
-import { colorFormat, getFormat } from './format';
+import { getFormat } from './format';
 
 export const Transports = {
   console: (options?: winston.transports.ConsoleTransportOptions) => new winston.transports.Console(options),
@@ -38,7 +38,7 @@ export const getTransports = (options: LoggerOptions) => {
   const transports = {
     console: () =>
       Transports.console({
-        format: winston.format.combine(winston.format.colorize(), colorFormat, format),
+        format: winston.format.combine(format),
       }),
     file: () =>
       Transports.file({

packages/core/server/src/application.ts

@@ -4,12 +4,13 @@ import { actions as authActions, AuthManager, AuthManagerOptions } from '@nocoba
 import { Cache, CacheManager, CacheManagerOptions } from '@nocobase/cache';
 import Database, { CollectionOptions, IDatabaseOptions } from '@nocobase/database';
 import {
-  AppLogger,
-  AppLoggerOptions,
-  createAppLogger,
+  SystemLogger,
+  RequestLoggerOptions,
   createLogger,
   getLoggerFilePath,
   LoggerOptions,
+  SystemLoggerOptions,
+  createSystemLogger,
 } from '@nocobase/logger';
 import { ResourceOptions, Resourcer } from '@nocobase/resourcer';
 import { applyMixins, AsyncEmitter, measureExecutionTime, Toposort, ToposortOptions } from '@nocobase/utils';
@@ -51,6 +52,11 @@ export interface ResourcerOptions {
   prefix?: string;
 }
 
+export interface AppLoggerOptions {
+  request: RequestLoggerOptions;
+  system: SystemLoggerOptions;
+}
+
 export interface ApplicationOptions {
   database?: IDatabaseOptions | Database;
   cacheManager?: CacheManagerOptions;
@@ -175,7 +181,7 @@ export class Application<StateT = DefaultState, ContextT = DefaultContext> exten
     return this._db;
   }
 
-  protected _logger: AppLogger;
+  protected _logger: SystemLogger;
 
   get logger() {
     return this._logger;
@@ -702,11 +708,14 @@ export class Application<StateT = DefaultState, ContextT = DefaultContext> exten
   protected init() {
     const options = this.options;
 
-    this._logger = createAppLogger({
-      app: this.name,
+    this._logger = createSystemLogger({
+      dirname: getLoggerFilePath(this.name),
+      filename: 'system',
+      seperateError: true,
       ...(options.logger?.system || {}),
     }).child({
       reqId: this.context.reqId,
+      app: this.name,
       module: 'application',
     });
 
@@ -787,7 +796,7 @@ export class Application<StateT = DefaultState, ContextT = DefaultContext> exten
       if (msg.includes('INSERT INTO')) {
         msg = msg.substring(0, 2000) + '...';
       }
-      sqlLogger.debug({ reqId: this.context.reqId, message: msg });
+      sqlLogger.debug({ message: msg, app: this.name, reqId: this.context.reqId });
     };
     const dbOptions = options.database instanceof Database ? options.database.options : options.database;
     const db = new Database({

packages/core/server/src/gateway/index.ts

@@ -1,4 +1,4 @@
-import { Toposort, ToposortOptions, uid } from '@nocobase/utils';
+import { Registry, Toposort, ToposortOptions, uid } from '@nocobase/utils';
 import { createStoragePluginsSymlink } from '@nocobase/utils/plugin-symlink';
 import { Command } from 'commander';
 import compression from 'compression';
@@ -19,7 +19,7 @@ import { applyErrorWithArgs, getErrorWithCode } from './errors';
 import { IPCSocketClient } from './ipc-socket-client';
 import { IPCSocketServer } from './ipc-socket-server';
 import { WSServer } from './ws-server';
-import { createLogger } from '@nocobase/logger';
+import { Logger, SystemLogger, createSystemLogger, getLoggerFilePath } from '@nocobase/logger';
 import { randomUUID } from 'crypto';
 
 const compress = promisify(compression());
@@ -61,6 +61,8 @@ export class Gateway extends EventEmitter {
   private wsServer: WSServer;
   private socketPath = xpipe.eq(resolve(process.cwd(), 'storage', 'gateway.sock'));
 
+  loggers = new Registry<SystemLogger>();
+
   private constructor() {
     super();
     this.reset();
@@ -126,11 +128,22 @@ export class Gateway extends EventEmitter {
     this.emit('appSelectorChanged');
   }
 
-  async logger(req: IncomingRequest) {
+  getLogger(appName: string, res: ServerResponse) {
     const reqId = randomUUID();
-    const appName = await this.getRequestHandleAppName(req);
-    req.headers['reqId'] = reqId;
-    return createLogger({ filename: `${appName}_request` }).child({ reqId });
+    res.setHeader('X-Request-Id', reqId);
+    let logger = this.loggers.get(appName);
+    if (logger) {
+      return logger.child({ reqId });
+    }
+    logger = createSystemLogger({
+      dirname: getLoggerFilePath(appName),
+      filename: 'system',
+      defaultMeta: {
+        app: appName,
+        module: 'gateway',
+      },
+    });
+    return logger.child({ reqId });
   }
 
   responseError(
@@ -148,7 +161,10 @@ export class Gateway extends EventEmitter {
   }
 
   responseErrorWithCode(code, res, options) {
-    this.responseError(res, applyErrorWithArgs(getErrorWithCode(code), options));
+    const log = this.getLogger(options.appName, res);
+    const error = applyErrorWithArgs(getErrorWithCode(code), options);
+    log.error(error.message, { method: 'responseErrorWithCode', error });
+    this.responseError(res, error);
   }
 
   async requestHandler(req: IncomingMessage, res: ServerResponse) {
@@ -197,6 +213,7 @@ export class Gateway extends EventEmitter {
     }
 
     const handleApp = await this.getRequestHandleAppName(req as IncomingRequest);
+    const log = this.getLogger(handleApp, res);
 
     const hasApp = AppSupervisor.getInstance().hasApp(handleApp);
 
@@ -207,6 +224,7 @@ export class Gateway extends EventEmitter {
     let appStatus = AppSupervisor.getInstance().getAppStatus(handleApp, 'initializing');
 
     if (appStatus === 'not_found') {
+      log.warn(`app not found`, { method: 'requestHandler' });
       this.responseErrorWithCode('APP_NOT_FOUND', res, { appName: handleApp });
       return;
     }
@@ -225,7 +243,8 @@ export class Gateway extends EventEmitter {
     const app = await AppSupervisor.getInstance().getApp(handleApp);
 
     if (appStatus !== 'running') {
-      this.responseErrorWithCode(`${appStatus}`, res, { app });
+      log.warn(`app is not running`, { method: 'requestHandler', status: appStatus });
+      this.responseErrorWithCode(`${appStatus}`, res, { app, appName: handleApp });
       return;
     }
 

packages/core/server/src/helper.ts

@@ -46,7 +46,7 @@ export function registerMiddlewares(app: Application, options: ApplicationOption
     app.context.reqId = randomUUID();
     await next();
   });
-  app.use(requestLogger(app.name, options.logger), { tag: 'logger' });
+  app.use(requestLogger(app.name, options.logger?.request), { tag: 'logger' });
   app.use(
     cors({
       exposeHeaders: ['content-disposition'],