import { format } from "node:util"; import { WriteStream, createWriteStream, existsSync, readFileSync, readdirSync } from "node:fs"; import { extname, resolve } from "node:path"; import { IncomingMessage } from "node:http"; import { ConfigOutput, ErrorHandler, Handler, LoadConfigOut, LogLevel, LoggerErrorEvent, LoggerFactory, LoggerFactoryArgs, LoggerFormatter, LoggerTransport, LoggerTransportWriteArgs, MinimalLogger, Request, Response, WriteArgs, newURL, normalizePath } from "./types.js"; /** * Logger */ export function LoggerHandler(options?: { formatter: (req: Request) => string; }): Handler { return function LoggerHandler(req, res): void { res.on("close", () => { const took = Date.now() - req.startMS; const entry = options ? [options.formatter(req), []] : ["status[%s] content-length[%s] [%s]ms", [res.statusCode, (res as any)._contentLength, took]]; if (res.statusCode < 400) { req.logger.info(entry[0], ...entry[1]); } else if (res.statusCode >= 400 && res.statusCode < 500) { req.logger.warn(entry[0], ...entry[1]); } else { req.logger.error(entry[0], ...entry[1]); } }); } } export interface Logger extends MinimalLogger { addTransport(transport: LoggerTransport): void; setLevel(level: LogLevel): void; } export class Logger extends EventTarget implements Logger { protected readonly options: { transports: LoggerTransport[]; formatter: LoggerFormatter; }; constructor(protected readonly identifier: string, protected level: LogLevel = "info", options?: { transports?: LoggerTransport[]; formatter?: LoggerFormatter; }) { super(); if (LOG_LEVEL_MAP[level] === undefined) { throw new Error(`Unknown level [${level}]`); } this.addEventListener(LoggerEvents.error, (ev: any) => { console.error((ev as LoggerErrorEvent).error); }); this.options = { transports: options && options.transports !== undefined ? options.transports : DEFAULT_LOGGER_TRANSPORTS(), formatter: options && options.formatter !== undefined ? options.formatter : DEFAULT_LOGGER_FORMATTER, }; } public setLevel(level: LogLevel): void { if (LOG_LEVEL_MAP[level] === undefined) { throw new Error(`Unknown level [${level}]`); } this.level = level; } public addTransport(transport: LoggerTransport): void { this.options.transports.push(transport); } protected write(args: WriteArgs): void { try { let eventArgs: LoggerTransportWriteArgs | undefined = undefined; const tR = []; for (const transport of this.options.transports) { if (LOG_LEVEL_MAP[transport.level ? transport.level : this.level] >= LOG_LEVEL_MAP[args.level]) { try { const createEventArg = () => { const originalArgs: WriteArgs = { optionalParams: args.optionalParams, identifier: this.identifier, level: args.level, message: args.message, meta: args.meta }; const out = this.options.formatter(originalArgs as { identifier: string; level: LogLevel; message: string; optionalParams: any[]; meta: any[]; }); return { out, ...originalArgs }; } eventArgs = eventArgs ? eventArgs : createEventArg(); tR.push(transport.write(eventArgs)); } catch (e2: any) { this.dispatchEvent(new LoggerErrorEvent(LoggerEvents.error, { error: e2 })); } } } Promise.allSettled(tR).catch((e) => { this.dispatchEvent(new LoggerErrorEvent(LoggerEvents.error, { error: e })); }); } catch (e: any) { this.dispatchEvent(new LoggerErrorEvent(LoggerEvents.error, { error: e })); } } /* eslint-disable @typescript-eslint/explicit-module-boundary-types */ public debug(message?: any, ...optionalParams: any[]): void { return this.write({ level: "debug", message, optionalParams, identifier: this.identifier, meta: [] }); } /* eslint-disable @typescript-eslint/explicit-module-boundary-types */ public error(message?: any, ...optionalParams: any[]): void { return this.write({ level: "error", message, optionalParams, identifier: this.identifier, meta: [] }); } /* eslint-disable @typescript-eslint/explicit-module-boundary-types */ public info(message?: any, ...optionalParams: any[]): void { return this.write({ level: "info", message, optionalParams, identifier: this.identifier, meta: [] }); } /* eslint-disable @typescript-eslint/explicit-module-boundary-types */ public log(message?: any, ...optionalParams: any[]): void { return this.write({ level: "info", message, optionalParams, identifier: this.identifier, meta: [] }); } /* eslint-disable @typescript-eslint/explicit-module-boundary-types */ public trace(message?: any, ...optionalParams: any[]): void { return this.write({ level: "trace", message, optionalParams, identifier: this.identifier, meta: [] }); } /* eslint-disable @typescript-eslint/explicit-module-boundary-types */ public warn(message?: any, ...optionalParams: any[]): void { return this.write({ level: "warn", message, optionalParams, identifier: this.identifier, meta: [] }); } } const FILE_TRANSPORT_ENV_VARIABLE = "LOG_FILE"; const FileTransportCacheMap: { [filePath: string]: { fileHandler: WriteStream | null; lastWrite: number; flushBuffer: string; currentTimeout: null | NodeJS.Timeout; } } = { } const FILE_TRANSPORT_TIMEOUT = 150; const FILE_TRANSPORT_THRESHOLD = 2 * 1024 * 1024; export const FileTransport: (filePath?: string | null, level?: LogLevel) => LoggerTransport = (filePath = process.env[FILE_TRANSPORT_ENV_VARIABLE] ? process.env[FILE_TRANSPORT_ENV_VARIABLE] : null, level?: LogLevel) => { if (filePath && !FileTransportCacheMap[filePath]) { FileTransportCacheMap[filePath] = { fileHandler: null, lastWrite: Date.now(), flushBuffer: "", currentTimeout: null, }; } return { level, write: ({ out }: LoggerTransportWriteArgs) => { if (filePath) { function flush(f?: boolean) { const fileHandler = filePath ? FileTransportCacheMap[filePath].fileHandler ? FileTransportCacheMap[filePath].fileHandler : createWriteStream(resolve(filePath), { flags: "a" }) : null; if (fileHandler && filePath && FileTransportCacheMap[filePath].flushBuffer) { if (!FileTransportCacheMap[filePath].fileHandler) { FileTransportCacheMap[filePath].fileHandler = fileHandler; fileHandler.on("error", (err) => { console.error(err); FileTransportCacheMap[filePath].fileHandler = null; }); } /*console.log("\n\nflushing [" + process.pid + "] LOG_FILE(" + (f ? "(1)" : "(2)") + ")\n\n"); console.log("\n\nflushing [" + FileTransportCacheMap[filePath].flushBuffer.split("\n").length + "] lines\n\n");*/ FileTransportCacheMap[filePath].lastWrite = Date.now(); const oldBuffer = FileTransportCacheMap[filePath].flushBuffer; FileTransportCacheMap[filePath].flushBuffer = ""; fileHandler.write(oldBuffer, (err) => { if (err) { console.error(err); } }); } } function createTimeoutFunction() { if (filePath) { clearTimeout(FileTransportCacheMap[filePath].currentTimeout as any); FileTransportCacheMap[filePath].currentTimeout = null; return () => { clearTimeout(FileTransportCacheMap[filePath].currentTimeout as any); FileTransportCacheMap[filePath].currentTimeout = null; if (filePath) { const now = Date.now(); /*console.log("\n\nflushing LOG_FILE ? " + process.pid + " " + lastWrite + "," + now + "\n\n"); console.log("\n\nflushing LOG_FILE ? " + process.pid + " " + (now - lastWrite) + "\n\n");*/ if (FileTransportCacheMap[filePath].flushBuffer && (now - FileTransportCacheMap[filePath].lastWrite > FILE_TRANSPORT_TIMEOUT || FileTransportCacheMap[filePath].flushBuffer.length > FILE_TRANSPORT_THRESHOLD) ) { flush(false); } } }; } return () => { }; } const now = Date.now(); FileTransportCacheMap[filePath].flushBuffer += `${out}\n`; if ((now - FileTransportCacheMap[filePath].lastWrite > FILE_TRANSPORT_TIMEOUT || FileTransportCacheMap[filePath].flushBuffer.length > FILE_TRANSPORT_THRESHOLD)) { clearTimeout(FileTransportCacheMap[filePath].currentTimeout as any); FileTransportCacheMap[filePath].currentTimeout = null; return flush(true); } else { //if (currentTimeout !== null) { clearTimeout(FileTransportCacheMap[filePath].currentTimeout as any); FileTransportCacheMap[filePath].currentTimeout = null; //} FileTransportCacheMap[filePath].currentTimeout = setTimeout(createTimeoutFunction(), FILE_TRANSPORT_TIMEOUT * 2); } } return; } }; }; export function ConsoleTransport(color: boolean = true, level?: LogLevel) { return { level, write: ({ level, out }: LoggerTransportWriteArgs) => { if (color) { switch (level) { case "warn": console.warn("\x1b[33m%s\x1b[0m", out); break; case "error": console.error("\x1b[31m%s\x1b[0m", out); break; case "trace": console.log("\x1b[34m%s\x1b[0m", out); break; case "debug": console.log("\x1b[36m%s\x1b[0m", out); break; case "none": break; default: console[level](out); break; } } else { if (level === "trace" || level === "debug") { console.log(out); } else if (level !== "none") { console[level](out); } } } }; } export const DEFAULT_LOGGER_TRANSPORTS: () => LoggerTransport[] = () => [ ConsoleTransport(), FileTransport() ]; export const DEFAULT_LOGGER_FORMATTER: LoggerFormatter = ({ identifier, level, message, optionalParams }) => format(`${new Date().toISOString()} ${process.pid} ` + `${identifier ? `[${identifier}] ` : ""}` + `${level !== "info" ? (level === "error" || level === "warn" ? `[${level.toUpperCase()}] ` : `[${level}] `) : ""}` + `${message}`, ...optionalParams); export const LOG_LEVEL_MAP = { "none": 0, "error": 1, "warn": 2, "info": 3, "debug": 4, "trace": 5, }; export const LoggerEvents = { error: "error" }; const loggerContainer: Map = new Map(); const DEFAULT_ENV_NAME = "LOG_LEVEL"; export function getLogger(identifier: string, options?: { formatter?: LoggerFormatter, transports?: LoggerTransport[] }, useCache = true): Logger { if (typeof identifier !== "string" && typeof identifier !== "undefined") { throw new Error("Bad log identifier"); } if (useCache && loggerContainer.has(identifier)) { return loggerContainer.get(identifier) as Logger; } else { const envVarName = `LOG_LEVEL_${identifier}`; const level = getEnvVariable(envVarName) ? getEnvVariable(envVarName) as LogLevel : getEnvVariable(DEFAULT_ENV_NAME, "info") as LogLevel const factory = getLoggerFactory(); const logger = factory({ identifier, level, options }); if (useCache) { loggerContainer.set(identifier, logger); } return logger; } }; function defaultLoggerFactory({ identifier, options, level }: LoggerFactoryArgs): Logger { return new Logger(identifier, level, { formatter: options && options.formatter ? options.formatter : DEFAULT_LOGGER_FORMATTER, transports: options && options.transports ? options.transports : DEFAULT_LOGGER_TRANSPORTS() }); }; let customLoggerFactory: LoggerFactory | undefined = undefined; export function setLoggerFactory(factory: LoggerFactory): LoggerFactory { if (customLoggerFactory !== undefined) { throw new Error("cannot change logger factory after it has been used."); } customLoggerFactory = factory; return customLoggerFactory; }; export function getLoggerFactory(): LoggerFactory { if (customLoggerFactory) { return customLoggerFactory; } else { customLoggerFactory = defaultLoggerFactory; return defaultLoggerFactory; } }; export function routerDefaultLoggerFactory(uuid: string, req: IncomingMessage): Logger { let path = ""; let query = ""; let urlParsingError; let method = "GET"; let remoteAddress: string | undefined = ""; try { const url = newURL(req.url ? req.url : "/") as URL; query = ""; //url.searchParams.toString(); path = normalizePath(url.pathname); // normalized path method = req.method ? req.method.toUpperCase() as string : "GET"; remoteAddress = req.socket.remoteAddress; } catch (e) { urlParsingError = e; } const pathToEnv = path.replace(/\//ig, "_").replace(/\./ig, "_").replace(/-/ig, "_").toUpperCase(); const WORKER_IDENTIFIER = process.env["CLUSTER_NODE_NUMBER"] ? `WORKER_${process.env["CLUSTER_NODE_NUMBER"]}_` : ""; const identifier = `${pathToEnv === "_" ? "" : `${pathToEnv.substring(1)}`}${pathToEnv.charAt(pathToEnv.length - 1) !== "_" ? "_" : ""}${method.toUpperCase()}`; const upgrade = req.headers.connection?.indexOf("Upgrade") !== -1; const logger = getLogger(`${WORKER_IDENTIFIER}${identifier}`, { formatter: (args: WriteArgs) => { args.message = `%s${upgrade ? " UPGRADE" : ""} %s%s [%s] (%s) ${args.message}`; args.optionalParams = [method, path, query ? `?${query}` : "", uuid, remoteAddress].concat(args.optionalParams); args.meta.push(req); args.meta.push(uuid); return DEFAULT_LOGGER_FORMATTER(args); } }, false); if (urlParsingError) { logger.error(urlParsingError); } return logger; } /** * Error */ export class BadRequestError extends Error { constructor(message = "BAD REQUEST") { super(message); this.name = "BadRequestError"; } } export class ConfigFileNotFoundError extends Error { constructor(message = "NOT FOUND") { super(message); this.name = "ConfigFileNotFoundError"; } } export class ForbiddenError extends Error { constructor(message = "FORBIDDEN") { super(message); this.name = "ForbiddenError"; } } export class NotFoundError extends Error { constructor(message = "NOT FOUND") { super(message); this.name = "NotFoundError"; } } export class MethodNotImplementedError extends Error { constructor(message = "NOT IMPLEMENTED") { super(message); this.name = "MethodNotImplementedError"; } } export class UnAuthorizedError extends Error { constructor(message = "UNAUTHORIZED") { super(message); this.name = "UnAuthorizedError"; } } export const HTML_HEADERS = { ["Content-Type"]: "text/html; charset=utf-8" } export const STATUS = { ERROR: 503, BAD_REQUEST: 400, NOT_FOUND: 404, NOT_IMPLEMENTED: 501, FORBIDDEN: 403, UNAUTHORIZED: 401, }; export function defaultAppErrorHandler(): ErrorHandler { const isTestEnv = (process.env.NODE_ENV === "development" || process.env.NODE_ENV === "test"); return async function DefaultErrorHandler(e: any, req: Request, res: Response): Promise { if ( isTestEnv && (!e || !e.name || e.name === "Error") ) { req.logger.error(e); await res.asyncEnd({ headers: HTML_HEADERS, status: STATUS.ERROR, body: `${e && e.message ? e.message : String(e)}. You are seeing this message because NODE_ENV === "development" || NODE_ENV === "test"${e && e.stack ? ` ${e.stack}` : ""}` }); } else { req.logger.error(e); const name = e && e.name ? e.name : undefined; switch (name) { case "NotFoundError": await res.asyncEnd({ headers: HTML_HEADERS, status: STATUS.NOT_FOUND, body: e.message ? e.message : "NOT FOUND" }); break; case "MethodNotImplementedError": await res.asyncEnd({ headers: HTML_HEADERS, status: STATUS.NOT_IMPLEMENTED, body: e.message ? e.message : "NOT IMPLEMENTED" }); break; case "ForbiddenError": await res.asyncEnd({ headers: HTML_HEADERS, status: STATUS.FORBIDDEN, body: e.message ? e.message : "FORBIDDEN" }); break; case "UnAuthorizedError": await res.asyncEnd({ headers: HTML_HEADERS, status: STATUS.UNAUTHORIZED, body: e.message ? e.message : "UNAUTHORIZED" }); break; case "ParseOptionsError": case "BadRequestError": case "SequelizeValidationError": case "SequelizeEagerLoadingError": case "SequelizeUniqueConstraintError": await res.asyncEnd({ headers: HTML_HEADERS, status: STATUS.BAD_REQUEST, body: e.message ? e.message : "BAD REQUEST" }); break; case "ConfigFileNotFoundError": await res.asyncEnd({ headers: HTML_HEADERS, status: STATUS.ERROR, body: e.message ? e.message : "SERVER ERROR" }); break; } } }; } /** * config loading */ export abstract class ConfigPathResolver { public static getSequelizeRCFilePath(): string { return resolve(ConfigPathResolver.getBaseDirname(), `.sequelizerc`); } public static getConfigDirname(): string { return resolve(ConfigPathResolver.getBaseDirname(), `config`, checkEnvVariable("NODE_ENV", "development")); } public static getBaseDirname(): string { const appBaseDirname = getEnvVariable("APP_BASE_DIRNAME"); if (appBaseDirname) { return appBaseDirname; } else if (typeof process !== "undefined") { return process.cwd(); } else { return ""; } } } export const checkEnvVariables = (requiredEnvVariables: string[], defaults?: string[]): string[] => { if (defaults && defaults.length !== requiredEnvVariables.length) { throw new Error(`defaults cannot be a different length of requiredEnvVariables`); } return requiredEnvVariables.map((envName, index) => checkEnvVariable(envName, defaults && defaults[index] ? defaults[index] : undefined)); }; export const checkEnvVariable = (envName: string, defaults?: string): string => { const value = getEnvVariable(envName, defaults); if (!value) { throw new Error(`Env variable [${envName}!] not defined.`); } return value; }; export const getEnvVariable = (envName: string, defaults?: string): string | undefined => { return process.env[envName] ? process.env[envName] : defaults ? defaults as string : undefined; }; export const isFeatureEnabled = (feature: string, defaults = true): boolean => { const featureToggleName = `${feature.toUpperCase()}`; return checkEnvVariable(featureToggleName, String(defaults)) === "true"; }; export const loadConfigString = (envFileContent: string, combined?: ConfigOutput): ConfigOutput => { const ret: ConfigOutput = Object.create(null); envFileContent.split("\n") .filter(value => value && value.length > 0 && value.substring(0, 1) !== "#") .forEach((line) => { const separator = line.indexOf("="); if (separator === -1) { throw new Error(`cannot read ${line}`); } ret[line.substring(0, separator)] = line.substring(separator + 1); }); const keys = Object.keys(ret); for (const key of keys) { if (combined) { combined[key] = ret[key]; } process.env[key] = ret[key]; } return ret; } export const loadConfigFile = (envFilePath: string, combined?: ConfigOutput, logger?: Logger): ConfigOutput => { if (!existsSync(envFilePath)) { throw new ConfigFileNotFoundError(`config file [${envFilePath}] doesnt exists!`); } else { if (logger) { logger.trace(`loading config from [${envFilePath}].`); } return loadConfigString(readFileSync(envFilePath).toString(), combined); } }; const MISSED_TO_RUNMIQRO_INIT = (configDirname: string): string => `no config loaded. env files in [${configDirname}] doesnt exist!.`; export const loadConfig = (configDirname: string = ConfigPathResolver.getConfigDirname(), logger?: Logger): LoadConfigOut => { const outputs: ConfigOutput[] = []; const combined = Object.create(null); //console.log(configDirname); if (existsSync(configDirname)) { const configFiles = readdirSync(configDirname); for (const configFile of configFiles) { const configFilePath = resolve(configDirname, configFile); const ext = extname(configFilePath); if (ext === ".env") { outputs.push(loadConfigFile(configFilePath, combined, logger)); } } if (logger && configFiles.length === 0) { logger.debug(MISSED_TO_RUNMIQRO_INIT(configDirname)); } } else if (logger) { logger.debug(MISSED_TO_RUNMIQRO_INIT(configDirname)); } return { combined, outputs }; };