diff --git a/server/.github/test.conf.json5 b/server/.github/test.conf.json5 index c49393dd4..1e80a3800 100644 --- a/server/.github/test.conf.json5 +++ b/server/.github/test.conf.json5 @@ -2,7 +2,6 @@ { MONGO_DATABASE_NAME: "testingdb", - LOG_LEVEL: "info", CAPTCHA_SECRET_KEY: "unused", SESSION_SECRET: "unused", FLO_API_URL: "https://flo.example.com", @@ -65,4 +64,9 @@ "api/min-sdvx", ], }, + LOGGER_CONFIG: { + FILE: false, + CONSOLE: true, + LOG_LEVEL: "info", + }, } diff --git a/server/package.json b/server/package.json index f5e21e85e..8ff6a08ce 100644 --- a/server/package.json +++ b/server/package.json @@ -51,6 +51,7 @@ "@types/bull": "^3.15.5", "@types/bunyan": "^1.8.7", "@types/deep-equal": "^1.0.1", + "@valuabletouch/winston-seq": "^1.2.0", "bcryptjs": "^2.4.3", "bull": "^4.1.0", "bunyan": "^1.8.15", @@ -79,6 +80,7 @@ "redis": "3.1.2", "rimraf": "3.0.2", "safe-json-stringify": "1.2.0", + "seq-logging": "^1.1.1", "tachi-common": "0.2.42", "ts-node": "10.0.0", "typescript": "4.3.4", diff --git a/server/pnpm-lock.yaml b/server/pnpm-lock.yaml index a33041a2a..7fbf904a1 100644 --- a/server/pnpm-lock.yaml +++ b/server/pnpm-lock.yaml @@ -24,6 +24,7 @@ specifiers: '@types/uuid': 8.3.0 '@typescript-eslint/eslint-plugin': 4.28.0 '@typescript-eslint/parser': 4.28.0 + '@valuabletouch/winston-seq': ^1.2.0 bcryptjs: ^2.4.3 bull: ^4.1.0 bunyan: ^1.8.15 @@ -59,6 +60,7 @@ specifiers: redis: 3.1.2 rimraf: 3.0.2 safe-json-stringify: 1.2.0 + seq-logging: ^1.1.1 supertest: 6.1.3 tachi-common: 0.2.42 tap: 15.0.9 @@ -74,6 +76,7 @@ dependencies: '@types/bull': 3.15.5 '@types/bunyan': 1.8.7 '@types/deep-equal': 1.0.1 + '@valuabletouch/winston-seq': 1.2.0 bcryptjs: 2.4.3 bull: 4.1.0 bunyan: 1.8.15 @@ -102,6 +105,7 @@ dependencies: redis: 3.1.2 rimraf: 3.0.2 safe-json-stringify: 1.2.0 + seq-logging: 1.1.1 tachi-common: 0.2.42 ts-node: 10.0.0_83f53b0a0c5616d3fa00ed4e30b9ce1b typescript: 4.3.4 @@ -834,6 +838,13 @@ packages: eslint-visitor-keys: 2.1.0 dev: true + /@valuabletouch/winston-seq/1.2.0: + resolution: {integrity: sha512-w29tdQQBcGk2Wp+LNGVnW36OYxyW1cRToCWFehOxshhEcqZFdJvWbnvgiN5aU1VRY7CIV8P0MEMKBHyQq3jhTg==} + dependencies: + seq-logging: 1.1.1 + winston-transport: 4.4.0 + dev: false + /accepts/1.3.7: resolution: {integrity: sha512-Il80Qs2WjYlJIBNzNkK6KYqlVMTbZLXgHx2oT0pU/fjRHyEp+PEfEPY0R3WCwAGVOtauxh1hOxNgIf5bv7dQpA==} engines: {node: '>= 0.6'} @@ -3847,6 +3858,10 @@ packages: statuses: 1.5.0 dev: false + /seq-logging/1.1.1: + resolution: {integrity: sha512-9miWILWu22dKNCkZi2UePAnZeQEzaYsQRKbAi5eSBUbuOyyeYPyYO1bEvIvZAZRjltEwY1S0yz94hc0/f+niDg==} + dev: false + /serve-static/1.14.1: resolution: {integrity: sha512-JMrvUwE54emCYWlTI+hGrGv5I8dEwmco/00EvkzIIsR7MqrHonbD9pO2MOfFnpFntl7ecpZs+3mW+XbQZu9QCg==} engines: {node: '>= 0.8.0'} diff --git a/server/src/lib/logger/discord-transport.ts b/server/src/lib/logger/discord-transport.ts index e60e146d7..edf9153cf 100644 --- a/server/src/lib/logger/discord-transport.ts +++ b/server/src/lib/logger/discord-transport.ts @@ -1,14 +1,22 @@ +/* eslint-disable @typescript-eslint/no-explicit-any */ import { ServerConfig } from "lib/setup/config"; import SafeJSONStringify from "safe-json-stringify"; import fetch from "utils/fetch"; import Transport, { TransportStreamOptions } from "winston-transport"; import { DiscordColours } from "./colours"; +import { integer } from "tachi-common"; +import { ONE_MINUTE } from "lib/constants/time"; interface DiscordTransportOptions extends TransportStreamOptions { /** Webhook obtained from Discord */ webhook: string; } +interface LogLevelCountState { + warn: integer; + error: integer; +} + /** * Creates a discord winston transport. This is a slightly adapted version * of sidhantpanda's winston-discord-transport, modified for our use case. @@ -22,9 +30,18 @@ export default class DiscordTransport extends Transport { /** Initialization promise resolved after retrieving discord id and token */ private initalised: Promise; + private bucketData: LogLevelCountState = { + warn: 0, + error: 0, + }; + + private isBucketing = false; + constructor(opts: DiscordTransportOptions) { super(opts); + this.resetBucketData(); + this.initalised = fetch(opts.webhook) .then((r) => { if (!r.ok) { @@ -38,12 +55,19 @@ export default class DiscordTransport extends Transport { }); } + private resetBucketData() { + this.bucketData = { + warn: 0, + error: 0, + }; + } + log(info: any, cb: () => void) { if (info.noDiscord !== false) { try { setImmediate(() => { this.initalised.then(() => { - this.SendToDiscord(this.webhookUrl, info); + this.handleSendToDiscord(info); }); }); } catch (err) { @@ -56,13 +80,62 @@ export default class DiscordTransport extends Transport { cb(); } - private GetWhoToTag() { - return ServerConfig.DISCORD_WHO_TO_TAG - ? ServerConfig.DISCORD_WHO_TO_TAG.map((e) => `<@${e}>`).join(" ") + private handleSendToDiscord(info: any) { + if (info.level === "crit" || info.level === "severe") { + return this.sendLogDirectlyToDiscord(info); + } + + if (!["warn", "error", "severe"].includes(info.level)) { + // Don't need to send notifications about these. + return; + } + + this.bucketData[info.level as "warn" | "error"] += 1; + + if (!this.isBucketing) { + this.isBucketing = true; + setTimeout(() => { + this.sendBucketData(); + }, ONE_MINUTE); + } + } + + private getWhoToTag() { + return ServerConfig.LOGGER_CONFIG.DISCORD!.WHO_TO_TAG + ? ServerConfig.LOGGER_CONFIG.DISCORD!.WHO_TO_TAG.map((e) => `<@${e}>`).join(" ") : "Nobody configured to tag, but this is bad, get someone!"; } - private async SendToDiscord(webhookLocation: string, info: any) { + private sendBucketData() { + let description = ""; + + // damn americans... + let color = 0; + + for (const key of ["warn", "error"] as const) { + if (this.bucketData[key]) { + description += `[${key.toUpperCase()}]: ${this.bucketData[key]}`; + color = DiscordColours[key]; + } + } + + const postBody = { + content: "", + embeds: [ + { + description, + color, + timestamp: new Date().toISOString(), + }, + ], + }; + + this.POSTData(postBody); + this.resetBucketData(); + this.isBucketing = false; + } + + private async sendLogDirectlyToDiscord(info: any) { const postBody = { content: "", embeds: [ @@ -82,11 +155,11 @@ export default class DiscordTransport extends Transport { // These two levels are bad, and require near-immediate attention. if (info.level === "severe") { - postBody.content = `SEVERE ERROR: ${this.GetWhoToTag()}\n${postBody.content}`; + postBody.content = `SEVERE ERROR: ${this.getWhoToTag()}\n${postBody.content}`; } if (info.level === "crit") { - postBody.content = `CRITICAL ERROR: ${this.GetWhoToTag()}\n${postBody.content}`; + postBody.content = `CRITICAL ERROR: ${this.getWhoToTag()}\n${postBody.content}`; } await this.POSTData(postBody); diff --git a/server/src/lib/logger/logger.test.ts b/server/src/lib/logger/logger.test.ts index aebb17a6a..7c0fc36df 100644 --- a/server/src/lib/logger/logger.test.ts +++ b/server/src/lib/logger/logger.test.ts @@ -3,7 +3,7 @@ import t from "tap"; import CreateLogCtx, { ChangeRootLogLevel, GetLogLevel, rootLogger, Transports } from "./logger"; -const LOG_LEVEL = ServerConfig.LOG_LEVEL; +const LOG_LEVEL = ServerConfig.LOGGER_CONFIG.LOG_LEVEL; t.test("Logger Tests", (t) => { const logger = CreateLogCtx(__filename); diff --git a/server/src/lib/logger/logger.ts b/server/src/lib/logger/logger.ts index 69000f6e2..bc19530b9 100644 --- a/server/src/lib/logger/logger.ts +++ b/server/src/lib/logger/logger.ts @@ -1,13 +1,15 @@ -import winston, { format, transports, Logger, LeveledLogMethod } from "winston"; -import { EscapeStringRegexp } from "utils/misc"; -import "winston-daily-rotate-file"; +import { Transport as SeqTransport } from "@valuabletouch/winston-seq"; +import { Environment, ServerConfig, TachiConfig } from "lib/setup/config"; import SafeJSONStringify from "safe-json-stringify"; -import { Environment, ServerConfig } from "lib/setup/config"; -import CreateDiscordWinstonTransport from "./discord-transport"; +import { SeqLogLevel } from "seq-logging"; +import { EscapeStringRegexp } from "utils/misc"; +import winston, { format, LeveledLogMethod, Logger, transports } from "winston"; +import "winston-daily-rotate-file"; +import DiscordWinstonTransport from "./discord-transport"; export type KtLogger = Logger & { severe: LeveledLogMethod }; -const level = process.env.LOG_LEVEL ?? ServerConfig.LOG_LEVEL; +const level = process.env.LOG_LEVEL ?? ServerConfig.LOGGER_CONFIG.LOG_LEVEL; const formatExcessProperties = (meta: Record, limit = false) => { let i = 0; @@ -116,20 +118,24 @@ const consoleFormatRoute = format.combine( }) ); -const tports: winston.transport[] = [ - new transports.DailyRotateFile({ - filename: "logs/tachi-%DATE%.log", - datePattern: "YYYY-MM-DD-HH", - zippedArchive: true, - maxSize: "20m", - maxFiles: "14d", - createSymlink: true, - symlinkName: "tachi.log", - format: defaultFormatRoute, - }), -]; +const tports: winston.transport[] = []; -if (!ServerConfig.NO_CONSOLE) { +if (ServerConfig.LOGGER_CONFIG.FILE) { + tports.push( + new transports.DailyRotateFile({ + filename: "logs/tachi-%DATE%.log", + datePattern: "YYYY-MM-DD-HH", + zippedArchive: true, + maxSize: "20m", + maxFiles: "14d", + createSymlink: true, + symlinkName: "tachi.log", + format: defaultFormatRoute, + }) + ); +} + +if (ServerConfig.LOGGER_CONFIG.CONSOLE) { tports.push( new transports.Console({ format: consoleFormatRoute, @@ -137,15 +143,41 @@ if (!ServerConfig.NO_CONSOLE) { ); } -if (ServerConfig.LOGGER_DISCORD_WEBHOOK) { +if (ServerConfig.LOGGER_CONFIG.DISCORD) { tports.push( - new CreateDiscordWinstonTransport({ - webhook: ServerConfig.LOGGER_DISCORD_WEBHOOK, + new DiscordWinstonTransport({ + webhook: ServerConfig.LOGGER_CONFIG.DISCORD.WEBHOOK_URL, level: "warn", }) ); } +if (ServerConfig.LOGGER_CONFIG.SEQ_API_KEY && Environment.seqUrl) { + // Turns winston log levels into seq format. + const levelMap: Record = { + crit: "Fatal", + severe: "Error", + error: "Error", + warn: "Warning", + info: "Information", + // Note that Seq interprets these in reverse, + // however, it's easier to read this code if I just + // use the same levels, instead of the right onesQ. + verbose: "Verbose", + debug: "Debug", + }; + + tports.push( + new SeqTransport({ + apiKey: ServerConfig.LOGGER_CONFIG.SEQ_API_KEY, + serverUrl: Environment.seqUrl, + levelMapper(level = "") { + return levelMap[level] ?? "information"; + }, + }) + ); +} + export const rootLogger = winston.createLogger({ levels: { crit: 0, // entire process termination is necessary @@ -159,10 +191,24 @@ export const rootLogger = winston.createLogger({ level, format: defaultFormatRoute, transports: tports, + defaultMeta: { + __ServerName: TachiConfig.NAME, + __Worker: !!process.env.IS_WORKER, + __ReplicaID: Environment.replicaIdentity, + }, }); -if (ServerConfig.LOGGER_DISCORD_WEBHOOK) { - rootLogger.info(`Discord logging enabled.`); +if (!!ServerConfig.LOGGER_CONFIG.SEQ_API_KEY !== !!Environment.seqUrl) { + rootLogger.warn( + `Only one of SEQ_API_KEY (conf.json5) and SEQ_URL (Environment) were set. Not sending logs to Seq, as both must be provided.` + ); +} + +if (tports.length === 0) { + // eslint-disable-next-line no-console + console.warn( + "You have no transports set. Absolutely no logs will be saved. This is a terrible idea!" + ); } function CreateLogCtx(filename: string, lg = rootLogger): KtLogger { diff --git a/server/src/lib/setup/config.ts b/server/src/lib/setup/config.ts index e96495565..43a11b98b 100644 --- a/server/src/lib/setup/config.ts +++ b/server/src/lib/setup/config.ts @@ -10,14 +10,8 @@ import { FormatPrError } from "utils/prudence"; dotenv.config(); // imports things like NODE_ENV from a local .env file if one is present. -const replicaInfo = process.env.REPLICA_IDENTITY ? ` (${process.env.REPLICA_IDENTITY})` : ""; - // stub - having a real logger here creates a circular dependency. -const logger = { - info: (...content: unknown[]) => console.log(replicaInfo, content), - error: (...content: unknown[]) => console.error(replicaInfo, content), - warn: (...content: unknown[]) => console.warn(replicaInfo, content), -}; // CreateLogCtx(__filename); +const logger = console; const confLocation = process.env.TCHIS_CONF_LOCATION ?? "./conf.json5"; @@ -54,7 +48,6 @@ export interface OAuth2Info { export interface TachiServerConfig { MONGO_DATABASE_NAME: string; - LOG_LEVEL: "debug" | "verbose" | "info" | "warn" | "error" | "severe" | "crit"; CAPTCHA_SECRET_KEY: string; SESSION_SECRET: string; FLO_API_URL?: string; @@ -71,7 +64,6 @@ export interface TachiServerConfig { RATE_LIMIT: integer; OAUTH_CLIENT_CAP: integer; OPTIONS_ALWAYS_SUCCEEDS?: boolean; - NO_CONSOLE?: boolean; EMAIL_CONFIG?: { FROM: string; DKIM?: SendMailOptions["dkim"]; @@ -85,8 +77,6 @@ export interface TachiServerConfig { USC_QUEUE_SIZE: integer; BEATORAJA_QUEUE_SIZE: integer; OUR_URL: string; - LOGGER_DISCORD_WEBHOOK?: string; - DISCORD_WHO_TO_TAG?: string[]; CDN_WEB_LOCATION: string; INVITE_CODE_CONFIG?: { BATCH_SIZE: integer; @@ -99,6 +89,16 @@ export interface TachiServerConfig { GAMES: Game[]; IMPORT_TYPES: ImportTypes[]; }; + LOGGER_CONFIG: { + LOG_LEVEL: "debug" | "verbose" | "info" | "warn" | "error" | "severe" | "crit"; + CONSOLE: boolean; + FILE: boolean; + SEQ_API_KEY: string | undefined; + DISCORD?: { + WEBHOOK_URL: string; + WHO_TO_TAG: string[]; + }; + }; } const isValidOauth2 = p.optional({ @@ -109,7 +109,6 @@ const isValidOauth2 = p.optional({ const err = p(config, { MONGO_DATABASE_NAME: "string", - LOG_LEVEL: p.isIn("debug", "verbose", "info", "warn", "error", "severe", "crit"), CAPTCHA_SECRET_KEY: "string", SESSION_SECRET: "string", FLO_API_URL: p.optional(isValidURL), @@ -126,7 +125,6 @@ const err = p(config, { RATE_LIMIT: p.optional(p.isPositiveInteger), OAUTH_CLIENT_CAP: p.optional(p.isPositiveInteger), OPTIONS_ALWAYS_SUCCEEDS: "*boolean", - NO_CONSOLE: "*boolean", EMAIL_CONFIG: p.optional({ FROM: "string", DKIM: "*object", @@ -152,6 +150,14 @@ const err = p(config, { GAMES: [p.isIn(StaticConfig.allSupportedGames)], IMPORT_TYPES: [p.isIn(StaticConfig.allImportTypes)], }, + LOGGER_CONFIG: { + LOG_LEVEL: p.optional( + p.isIn("debug", "verbose", "info", "warn", "error", "severe", "crit") + ), + CONSOLE: "*boolean", + FILE: "*boolean", + SEQ_API_KEY: "*string", + }, }); if (err) { @@ -166,6 +172,16 @@ tachiServerConfig.OAUTH_CLIENT_CAP ??= 15; tachiServerConfig.USC_QUEUE_SIZE ??= 3; tachiServerConfig.BEATORAJA_QUEUE_SIZE ??= 3; +// Assign sane defaults to the logger config. +tachiServerConfig.LOGGER_CONFIG = Object.assign( + { + LOG_LEVEL: "info", + CONSOLE: true, + FILE: true, + }, + tachiServerConfig.LOGGER_CONFIG +); + export const TachiConfig = tachiServerConfig.TACHI_CONFIG; export const ServerConfig = tachiServerConfig; @@ -189,6 +205,13 @@ if (!mongoUrl) { process.exit(1); } +const seqUrl = process.env.SEQ_URL; +if (!seqUrl && tachiServerConfig.LOGGER_CONFIG.SEQ_API_KEY) { + logger.warn( + `No SEQ_URL specified in environment, yet LOGGER_CONFIG.SEQ_API_KEY was defined. No logs will be sent to Seq!` + ); +} + const cdnRoot = process.env.CDN_FILE_ROOT; if (!cdnRoot) { logger.error(`No CDN_FILE_ROOT specified in environment. Terminating.`); @@ -209,11 +232,6 @@ if (!["dev", "production", "staging", "test"].includes(nodeEnv)) { } const replicaIdentity = process.env.REPLICA_IDENTITY; -if (!replicaIdentity) { - logger.info( - `No REPLICA_IDENTITY set in environment. We are not running in a distributed environment.` - ); -} export const Environment = { port, @@ -223,4 +241,5 @@ export const Environment = { cdnRoot: nodeEnv === "test" ? "./test-cdn" : cdnRoot, nodeEnv, replicaIdentity, + seqUrl, }; diff --git a/server/src/server/router/api/v1/admin/router.test.ts b/server/src/server/router/api/v1/admin/router.test.ts index 3665cba88..c831adeb1 100644 --- a/server/src/server/router/api/v1/admin/router.test.ts +++ b/server/src/server/router/api/v1/admin/router.test.ts @@ -10,7 +10,7 @@ import ResetDBState from "test-utils/resets"; import { TestingIIDXSPScore } from "test-utils/test-data"; import { ScoreDocument } from "tachi-common"; -const LOG_LEVEL = ServerConfig.LOG_LEVEL; +const LOG_LEVEL = ServerConfig.LOGGER_CONFIG.LOG_LEVEL; t.test("POST /api/v1/admin/change-log-level", async (t) => { t.beforeEach(() => { diff --git a/server/src/server/router/api/v1/admin/router.ts b/server/src/server/router/api/v1/admin/router.ts index a32d3f140..9fbba9334 100644 --- a/server/src/server/router/api/v1/admin/router.ts +++ b/server/src/server/router/api/v1/admin/router.ts @@ -47,7 +47,7 @@ const RequireAdminLevel: RequestHandler = async (req, res, next) => { return next(); }; -const LOG_LEVEL = ServerConfig.LOG_LEVEL; +const LOG_LEVEL = ServerConfig.LOGGER_CONFIG.LOG_LEVEL; router.use(RequireAdminLevel);