From 5ad695059e009d24aaf08b728300d9d50c45b2b3 Mon Sep 17 00:00:00 2001 From: Corban-Lee Jones Date: Fri, 16 May 2025 23:22:04 +0100 Subject: [PATCH] feat: add proper logging with winston --- .gitignore | 3 +- README.md | 2 + package.json | 1 + src/app.ts | 9 ++- src/bot/events/ready.ts | 5 +- src/bot/task.ts | 17 +++-- src/log.ts | 105 +++++++++++++++++++++++++--- src/server/middleware/requestLog.ts | 18 +++++ 8 files changed, 138 insertions(+), 22 deletions(-) create mode 100644 src/server/middleware/requestLog.ts diff --git a/.gitignore b/.gitignore index 8886101..113b719 100644 --- a/.gitignore +++ b/.gitignore @@ -1,6 +1,7 @@ dist/ node_modules/ -generated/prisma +generated/ +logs/ package-lock.json .env diff --git a/README.md b/README.md index 11ad962..ef3c085 100644 --- a/README.md +++ b/README.md @@ -16,3 +16,5 @@ |`CLIENT_ID`|Discord application client ID.|✔|| |`CLIENT_SECRET`|Discord application client secret.|✔|| |`DISCORD_USER_IDS`|CSV of Discord User IDs allowed to access the web ui.|✔|| +|`LOG_LEVEL`|Manually set the log level (not recommended).||`info`| +|`LOG_DIR`|Override the default output directory for log files.||| diff --git a/package.json b/package.json index 4b224a2..629d1b1 100644 --- a/package.json +++ b/package.json @@ -60,6 +60,7 @@ "@floating-ui/dom": "^1.6.13", "@prisma/client": "^6.6.0", "@tailwindcss/forms": "^0.5.10", + "chalk": "^5.4.1", "datatables.net-dt": "^2.2.2", "datatables.net-select": "^3.0.0", "datatables.net-select-dt": "^3.0.0", diff --git a/src/app.ts b/src/app.ts index 5407c12..0d4d3a5 100644 --- a/src/app.ts +++ b/src/app.ts @@ -11,6 +11,10 @@ import homeRouter from "@server/routers/home.router"; import guildRouter from "@server/routers/guild.router"; import { attachGuilds } from "@server/middleware/attachGuilds"; import { guildTabHelper } from "@server/middleware/guildTabHelper"; +import { requestLog } from "@server/middleware/requestLog"; +import { getLogger } from "./log"; + +const logger = getLogger(__filename); const app = express(); @@ -19,6 +23,7 @@ app.set("view engine", "ejs"); app.set("views", path.resolve(__dirname, "client/views")); app.use(express.urlencoded({ extended: true })); app.use(express.json()); +app.use(requestLog); app.use("/public", express.static(path.resolve(__dirname, "client/public"))); @@ -29,11 +34,11 @@ const HOST = process.env.HOST || "localhost"; const PORT = process.env.PORT || 3000; const server = app.listen(PORT, () => { - console.log(`Server is listening on port http://${HOST}:${PORT}`); + logger.info(`Server is listening on port http://${HOST}:${PORT}`); }); process.on("SIGINT", () => { - console.log("\nShutdown signal received..."); + logger.info("Shutdown signal received..."); prisma.$disconnect(); server.close(error => { diff --git a/src/bot/events/ready.ts b/src/bot/events/ready.ts index f238b62..0dc22dd 100644 --- a/src/bot/events/ready.ts +++ b/src/bot/events/ready.ts @@ -1,6 +1,9 @@ import { ActivityType } from "discord.js"; import Event from "@bot/components/event"; import DiscordBot from "@bot/bot"; +import { getLogger } from "src/log"; + +const logger = getLogger(__filename); export default class Ready extends Event { name = "ready"; @@ -14,6 +17,6 @@ export default class Ready extends Event { await client.interactions.deploy(); client.user.setActivity("new sources", {type: ActivityType.Watching}); - console.log(`Discord Bot ${client.user.displayName} is online!`); + logger.info(`Discord Bot ${client.user.displayName} is online!`) } } diff --git a/src/bot/task.ts b/src/bot/task.ts index 4c1730c..e00f339 100644 --- a/src/bot/task.ts +++ b/src/bot/task.ts @@ -4,6 +4,9 @@ import { parse as HtmlParser } from "node-html-parser"; import { Feed, Filter, MessageStyle, Channel, MatchingAlgorithms } from "../../generated/prisma"; import * as filters from "@bot/filter"; import prisma from "@server/prisma"; +import { getLogger } from "src/log"; + +const logger = getLogger(__filename); export const triggerTask = async (client: Client) => { for (const [_, guild] of client.guilds.cache) { @@ -42,7 +45,7 @@ const processFeed = async (feed: ExpandedFeed, client: Client) => { const parsed = await getParsedUrl(feed.url); if (!parsed) return; - console.log(`Processing feed: ${feed.name}`); + logger.debug(`Processing feed: ${feed.name}`); for (const channelId of feed.channels.map(channel => channel.channel_id)) { const channel = client.channels.cache.get(channelId); @@ -51,11 +54,11 @@ const processFeed = async (feed: ExpandedFeed, client: Client) => { }; const processItems = async (items: RssParser.Item[], feed: ExpandedFeed, channel: DiscordChannel) => { - console.log(`Processing ${items.length} items`); + logger.debug(`Processing ${items.length} items`); for (let i = items.length; i--;) { if (new Date(items[i].pubDate!) < feed.published_threshold) { - console.log(`skipping outdated item: ${items[i].title}`) + logger.debug(`skipping outdated item: ${items[i].title}`) items.splice(i, 1); continue; } @@ -65,15 +68,15 @@ const processItems = async (items: RssParser.Item[], feed: ExpandedFeed, channel } } - console.log(`Processing ${items.length} items (post-filter)`) + logger.debug(`Processing ${items.length} items (post-filter)`) const batchSize = 4; const totalBatches = Math.floor((items.length + batchSize - 1) / batchSize); - console.log(`batchSize: ${batchSize}, totalBatches: ${totalBatches}`) + logger.debug(`batchSize: ${batchSize}, totalBatches: ${totalBatches}`) for (let batchNumber = 0; batchNumber * batchSize < items.length; batchNumber++) { - console.log(`Processing items batch [${batchNumber+1}/${totalBatches}]`); + logger.debug(`Processing items batch [${batchNumber+1}/${totalBatches}]`); const i = batchNumber * batchSize; const batch = items.slice(i, i + batchSize); @@ -142,7 +145,7 @@ const passesFilter = async (filter: Filter, item: RssParser.Item) => { ); } - console.log(`Filter result: matchFound=${matchFound}, is_whitelist=${filter.is_whitelist}, willSend=${filter.is_whitelist ? matchFound : !matchFound}`); + logger.debug(`Filter result: matchFound=${matchFound}, is_whitelist=${filter.is_whitelist}, willSend=${filter.is_whitelist ? matchFound : !matchFound}`); return filter.is_whitelist ? matchFound : !matchFound; }; diff --git a/src/log.ts b/src/log.ts index 5dbcead..ef6977f 100644 --- a/src/log.ts +++ b/src/log.ts @@ -1,18 +1,101 @@ import winston from "winston"; +import chalk from "chalk"; +import path from "path"; +import fs from "fs"; -const { combine, timestamp, json, printf } = winston.format; +const logFileDirectory = process.env.LOG_DIR || path.join(__dirname, "..", "logs"); +if (!fs.existsSync(logFileDirectory)) { + fs.mkdirSync(logFileDirectory); +} + +const deleteLogFile =(filePath: string) => { + try { + fs.unlinkSync(filePath); + logger.info("Deleted expired log file", { filename: __filename }); + } catch (error) { + logger.error("Failed to expired log file:", error); + } +} + +const cleanExpiredLogFiles = () => { + const files = fs.readdirSync(logFileDirectory); + const now = Date.now(); + const maxAgeMs = 7 * 24 * 60 * 60 * 1000; + + for (const file of files) { + const filePath = path.join(logFileDirectory, file); + const stats = fs.statSync(filePath); + + if (stats.isFile() && now - stats.mtimeMs > maxAgeMs) { + deleteLogFile(filePath); + } + } +}; + +const { combine, timestamp, errors, printf } = winston.format; const timestampFormat = "YYYY-MM-DD HH:mm:ss"; +const levelColours: Record = { + info: chalk.green, + warn: chalk.yellow, + error: chalk.red, + debug: chalk.magenta, +} + +const consoleFormat = combine( + errors({ stack: true }), + timestamp({ format: timestampFormat }), + printf(({ timestamp, level, message, filename }) => { + const levelColour = levelColours[level] || chalk.white; + + level = levelColour(level); + timestamp = chalk.cyan(timestamp); + message = chalk.white(message); + filename = chalk.white(filename || "unknown") + + return `[${level}] (${filename}) ${timestamp}: ${message}`; + }) +); + +const consoleFormatHttp = combine( + errors({ stack: true }), + timestamp({ format: timestampFormat }), + printf(({ timestamp, level, method, path, status, duration }) => { + return `[${level}] ${timestamp} [${method}] (${status}) ${path} ${duration}ms`; + }) +); + +const fileFormat = combine( + errors({ stack: true }), + timestamp({ format: timestampFormat }), + printf(({ timestamp, level, message, filename }) => { + return `[${level}] (${filename || "unknown"}) ${timestamp}: ${message}`; + }) +); + +const sessionTimestamp = new Date().toISOString() + .replace(/T/, "_") + .replace(/:/g, "-") + .replace(/\..+/, ""); +const sessionLogFile = path.join(logFileDirectory, `${sessionTimestamp}.log`); export const logger = winston.createLogger({ - format: combine( - timestamp({ format: timestampFormat }), - json(), - printf(({ _timestamp, level, message, ...data }) => { - const response = { level, message, data }; - return JSON.stringify(response); - }) - ), + level: process.env.LOG_LEVEL || "info", + levels: winston.config.syslog.levels, transports: [ - new winston.transports.Console() + new winston.transports.Console({ + level: "debug", + format: consoleFormat + }), + new winston.transports.File({ + filename: sessionLogFile, + level: "info", + format: fileFormat + }) ] -}); \ No newline at end of file +}); + +cleanExpiredLogFiles(); + +export const getLogger = (file: string) => { + return logger.child({ filename: path.relative(__dirname, file).replace(/\\/g, "/") }); +} diff --git a/src/server/middleware/requestLog.ts b/src/server/middleware/requestLog.ts new file mode 100644 index 0000000..4eb7984 --- /dev/null +++ b/src/server/middleware/requestLog.ts @@ -0,0 +1,18 @@ +import { Request, Response, NextFunction } from "express"; +import { logger } from "src/log"; + +// const logger = getLogger(__filename); + +export const requestLog = (request: Request, response: Response, next: NextFunction) => { + // const start = Date.now(); + // response.on("finish", () => { + // const duration = Date.now() - start; + // httpLogger.info({ + // method: request.method, + // path: request.path, + // status: response.statusCode, + // duration: duration + // }); + // }); + next(); +}; \ No newline at end of file