From 318b4334828f5562fb56bf28dabfe5fa1fce5ed1 Mon Sep 17 00:00:00 2001 From: YANG QIA <2013xile@gmail.com> Date: Sat, 30 Dec 2023 23:34:40 +0800 Subject: [PATCH] chore(logger): improve format (#3290) * chore(logger): improve format * fix: build * feat: develop format * chore: develop -> console --- packages/core/app/src/config/logger.ts | 3 +- packages/core/logger/src/app-logger.ts | 23 ------- packages/core/logger/src/config.ts | 4 +- packages/core/logger/src/format.ts | 71 ++++++++++++++++------ packages/core/logger/src/index.ts | 1 - packages/core/logger/src/logger.ts | 17 +----- packages/core/logger/src/request-logger.ts | 22 ++++--- packages/core/logger/src/system-logger.ts | 28 +++++++-- packages/core/logger/src/transports.ts | 4 +- packages/core/server/src/application.ts | 23 ++++--- packages/core/server/src/gateway/index.ts | 35 ++++++++--- packages/core/server/src/helper.ts | 2 +- 12 files changed, 144 insertions(+), 89 deletions(-) delete mode 100644 packages/core/logger/src/app-logger.ts diff --git a/packages/core/app/src/config/logger.ts b/packages/core/app/src/config/logger.ts index 2126abcf9..3ee8cbb86 100644 --- a/packages/core/app/src/config/logger.ts +++ b/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: { diff --git a/packages/core/logger/src/app-logger.ts b/packages/core/logger/src/app-logger.ts deleted file mode 100644 index 82355cf4e..000000000 --- a/packages/core/logger/src/app-logger.ts +++ /dev/null @@ -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 { - info: logMethod; - warn: logMethod; - error: logMethod; - debug: logMethod; -} diff --git a/packages/core/logger/src/config.ts b/packages/core/logger/src/config.ts index aeaa67e02..296054797 100644 --- a/packages/core/logger/src/config.ts +++ b/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'); diff --git a/packages/core/logger/src/format.ts b/packages/core/logger/src/format.ts index 0730b4ccf..5a90a8605 100644 --- a/packages/core/logger/src/format.ts +++ b/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 }))(); diff --git a/packages/core/logger/src/index.ts b/packages/core/logger/src/index.ts index cd31685b8..18e521a52 100644 --- a/packages/core/logger/src/index.ts +++ b/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'; diff --git a/packages/core/logger/src/logger.ts b/packages/core/logger/src/logger.ts index 9218d2981..8062c71f8 100644 --- a/packages/core/logger/src/logger.ts +++ b/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 { 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; - requestWhitelist?: string[]; - responseWhitelist?: string[]; -} - -export interface AppLoggerOptions { - request: ReqeustLoggerOptions; - system: SystemLoggerOptions; -} diff --git a/packages/core/logger/src/request-logger.ts b/packages/core/logger/src/request-logger.ts index 372421711..d54661272 100644 --- a/packages/core/logger/src/request-logger.ts +++ b/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; + 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 }); diff --git a/packages/core/logger/src/system-logger.ts b/packages/core/logger/src/system-logger.ts index 5c2cd4fd1..bc7fa2887 100644 --- a/packages/core/logger/src/system-logger.ts +++ b/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 { + 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)], }); diff --git a/packages/core/logger/src/transports.ts b/packages/core/logger/src/transports.ts index 6a3899d8e..be60b53b2 100644 --- a/packages/core/logger/src/transports.ts +++ b/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({ diff --git a/packages/core/server/src/application.ts b/packages/core/server/src/application.ts index 4c7edfb03..4912062f6 100644 --- a/packages/core/server/src/application.ts +++ b/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 exten return this._db; } - protected _logger: AppLogger; + protected _logger: SystemLogger; get logger() { return this._logger; @@ -702,11 +708,14 @@ export class Application 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 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({ diff --git a/packages/core/server/src/gateway/index.ts b/packages/core/server/src/gateway/index.ts index ec3da5206..7b05b215e 100644 --- a/packages/core/server/src/gateway/index.ts +++ b/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(); + 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; } diff --git a/packages/core/server/src/helper.ts b/packages/core/server/src/helper.ts index f3cca7342..8d2e2c08b 100644 --- a/packages/core/server/src/helper.ts +++ b/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'],