From 2f130e876240a64a70588b025b39ebee71d2d34e Mon Sep 17 00:00:00 2001 From: Annika <56906084+AnnikaCodes@users.noreply.github.com> Date: Fri, 30 Oct 2020 16:27:25 -0700 Subject: [PATCH] Modlog: Support logging to a SQLite database (#7513) * Modlog: Support logging to a SQLite database Co-authored-by: Christopher Monsanto --- .eslintrc-no-types.json | 2 +- .gitignore | 3 +- databases/schemas/modlog.sql | 23 +++ package.json | 2 + server/chat-commands/admin.ts | 6 +- server/modlog.ts | 215 +++++++++++++++----- server/rooms.ts | 9 +- test/server/modlog.js | 350 +++++++++++++++------------------ test/tools/modlog/converter.js | 4 +- tools/modlog/convert | 2 +- tools/modlog/converter.ts | 178 ++++++++++++++++- 11 files changed, 545 insertions(+), 249 deletions(-) create mode 100644 databases/schemas/modlog.sql diff --git a/.eslintrc-no-types.json b/.eslintrc-no-types.json index ea10e103ee36..54d254b1208c 100644 --- a/.eslintrc-no-types.json +++ b/.eslintrc-no-types.json @@ -186,7 +186,7 @@ { "files": [ "./config/*.ts", "./data/**/*.ts", "./lib/*.ts", "./server/**/*.ts", "./sim/**/*.ts", - "./tools/set-import/*.ts", "./tools/modlog/*.ts", "./translations/**/*.ts" + "./tools/set-import/*.ts", "./tools/modlog/*.ts", "./translations/**/*.ts" ], "parser": "@typescript-eslint/parser", "parserOptions": { diff --git a/.gitignore b/.gitignore index aca3a56d103b..fae780aace8b 100644 --- a/.gitignore +++ b/.gitignore @@ -13,7 +13,8 @@ npm-debug.log package-lock.json /tools/set-import/sets databases/*.db* - +*.o +*.o.dSYM # Typescript build artifacts .*-dist/ tools/set-import/importer.js diff --git a/databases/schemas/modlog.sql b/databases/schemas/modlog.sql new file mode 100644 index 000000000000..d695c74b8715 --- /dev/null +++ b/databases/schemas/modlog.sql @@ -0,0 +1,23 @@ +CREATE TABLE modlog ( + modlog_id INTEGER NOT NULL PRIMARY KEY, + -- UNIX timestamp + timestamp INTEGER NOT NULL, + --- roomid OR global-roomid + roomid TEXT NOT NULL, + action TEXT NOT NULL, + visual_roomid TEXT, + action_taker_userid TEXT, + userid TEXT, + autoconfirmed_userid TEXT, + ip TEXT, + note TEXT +); + +CREATE TABLE alts ( + modlog_id INTEGER NOT NULL, + userid TEXT NOT NULL, + PRIMARY KEY (modlog_id, userid), + FOREIGN KEY (modlog_id) REFERENCES modlog(modlog_id) +) WITHOUT ROWID; + +PRAGMA journal_mode=WAL; diff --git a/package.json b/package.json index 19099d14f278..fd50a53c21dd 100644 --- a/package.json +++ b/package.json @@ -4,6 +4,8 @@ "version": "0.11.3", "main": ".sim-dist/index.js", "dependencies": { + "@types/better-sqlite3": "^5.4.0", + "better-sqlite3": "^7.1.0", "probe-image-size": "^5.0.0", "sockjs": "0.3.20", "sucrase": "^3.15.0" diff --git a/server/chat-commands/admin.ts b/server/chat-commands/admin.ts index d3486d156176..bac87460019f 100644 --- a/server/chat-commands/admin.ts +++ b/server/chat-commands/admin.ts @@ -431,7 +431,11 @@ export const commands: ChatCommands = { if (manager.filename.startsWith(FS('.server-dist/modlog').path)) void manager.destroy(); } - Rooms.Modlog = require('../modlog').modlog; + const {Modlog} = require('../modlog'); + Rooms.Modlog = new Modlog( + Rooms.MODLOG_PATH || 'logs/modlog', + Rooms.MODLOG_DB_PATH || `${__dirname}/../../databases/modlog.db` + ); this.sendReply("Modlog has been hot-patched."); Rooms.Modlog.streams = streams; Rooms.Modlog.sharedStreams = sharedStreams; diff --git a/server/modlog.ts b/server/modlog.ts index 34eac15d4451..0239bef5cbcd 100644 --- a/server/modlog.ts +++ b/server/modlog.ts @@ -14,6 +14,7 @@ import * as util from 'util'; import {FS} from '../lib/fs'; import {QueryProcessManager} from '../lib/process-manager'; import {Repl} from '../lib/repl'; +import * as Database from 'better-sqlite3'; import {checkRipgrepAvailability} from './config-loader'; import {parseModlog} from '../tools/modlog/converter'; @@ -21,7 +22,8 @@ import {parseModlog} from '../tools/modlog/converter'; const MAX_PROCESSES = 1; // If a modlog query takes longer than this, it will be logged. const LONG_QUERY_DURATION = 2000; -const MODLOG_PATH = 'logs/modlog'; + +const MODLOG_SCHEMA_PATH = 'databases/schemas/modlog.sql'; const GLOBAL_PUNISHMENTS = [ 'WEEKLOCK', 'LOCK', 'BAN', 'RANGEBAN', 'RANGELOCK', 'FORCERENAME', @@ -48,13 +50,19 @@ interface ModlogResults { duration?: number; } -interface ModlogQuery { +interface ModlogTextQuery { rooms: ModlogID[]; regexString: string; maxLines: number; onlyPunishments: boolean | string; } +interface ModlogSQLQuery { + statement: Database.Statement; + args: T[]; + returnsResults?: boolean; +} + export interface ModlogSearch { note?: {searches: string[], isExact?: boolean}; user?: {search: string, isExact?: boolean}; @@ -122,8 +130,84 @@ export class Modlog { sharedStreams: Map = new Map(); streams: Map = new Map(); - constructor(path: string) { - this.logPath = path; + readonly database: Database.Database; + + readonly modlogInsertionQuery: Database.Statement; + readonly altsInsertionQuery: Database.Statement<[number, string]>; + readonly renameQuery: Database.Statement<[string, string]>; + readonly insertionTransaction: Database.Transaction; + + constructor(flatFilePath: string, databasePath: string) { + this.logPath = flatFilePath; + + const dbExists = FS(databasePath).existsSync(); + + this.database = new Database(databasePath); + this.database.exec("PRAGMA foreign_keys = ON;"); + + // Set up tables, etc + + if (!dbExists) { + this.database.exec(FS(MODLOG_SCHEMA_PATH).readIfExistsSync()); + } + + let insertionQuerySource = `INSERT INTO modlog (timestamp, roomid, visual_roomid, action, userid, autoconfirmed_userid, ip, action_taker_userid, note)`; + insertionQuerySource += ` VALUES ($time, $roomID, $visualRoomID, $action, $userid, $autoconfirmedID, $ip, $loggedBy, $note)`; + this.modlogInsertionQuery = this.database.prepare(insertionQuerySource); + + this.altsInsertionQuery = this.database.prepare(`INSERT INTO alts (modlog_id, userid) VALUES (?, ?)`); + this.renameQuery = this.database.prepare(`UPDATE modlog SET roomid = ? WHERE roomid = ?`); + + this.insertionTransaction = this.database.transaction((entries: Iterable) => { + for (const entry of entries) { + if (!entry.visualRoomID) entry.visualRoomID = undefined; + if (!entry.userid) entry.userid = undefined; + if (!entry.autoconfirmedID) entry.autoconfirmedID = undefined; + if (!entry.ip) entry.ip = undefined; + if (!entry.loggedBy) entry.loggedBy = undefined; + if (!entry.note) entry.note = undefined; + + const result = this.modlogInsertionQuery.run(entry); + const rowid = result.lastInsertRowid as number; + + for (const alt of entry.alts || []) { + this.altsInsertionQuery.run(rowid, alt); + } + } + }); + } + + /****************** + * Helper methods * + ******************/ + formatArray(arr: unknown[], args: unknown[]) { + args.push(...arr); + return [...'?'.repeat(arr.length)].join(', '); + } + + getSharedID(roomid: ModlogID): ID | false { + return roomid.includes('-') ? `${toID(roomid.split('-')[0])}-rooms` as ID : false; + } + + runSQL(query: ModlogSQLQuery): Database.RunResult { + return query.statement.run(query.args); + } + + runSQLWithResults(query: ModlogSQLQuery): unknown[] { + return query.statement.all(query.args); + } + + generateIDRegex(search: string) { + // Ensure the generated regex can never be greater than or equal to the value of + // RegExpMacroAssembler::kMaxRegister in v8 (currently 1 << 16 - 1) given a + // search with max length MAX_QUERY_LENGTH. Otherwise, the modlog + // child process will crash when attempting to execute any RegExp + // constructed with it (i.e. when not configured to use ripgrep). + return `[^a-zA-Z0-9]?${[...search].join('[^a-zA-Z0-9]*')}([^a-zA-Z0-9]|\\z)`; + } + + escapeRegex(search: string) { + return search.replace(/[\\.+*?()|[\]{}^$]/g, '\\$&'); } /************************************** @@ -144,27 +228,47 @@ export class Modlog { this.streams.set(roomid, stream); } - getSharedID(roomid: ModlogID): ID | false { - return roomid.includes('-') ? `${toID(roomid.split('-')[0])}-rooms` as ID : false; - } - /** * Writes to the modlog */ write(roomid: string, entry: ModlogEntry, overrideID?: string) { - roomid = entry.roomID || roomid; - const stream = this.streams.get(roomid as ModlogID); - if (!stream) throw new Error(`Attempted to write to an uninitialized modlog stream for the room '${roomid}'`); - - let buf = `[${new Date(entry.time || Date.now()).toJSON()}] (${overrideID || entry.visualRoomID || roomid}) ${entry.action}:`; - if (entry.userid) buf += ` [${entry.userid}]`; - if (entry.autoconfirmedID) buf += ` ac:[${entry.autoconfirmedID}]`; - if (entry.alts) buf += ` alts:[${entry.alts.join('], [')}]`; - if (entry.ip) buf += ` [${entry.ip}]`; - if (entry.loggedBy) buf += ` by ${entry.loggedBy}`; - if (entry.note) buf += `: ${entry.note}`; - - void stream.write(`${buf}\n`); + if (!entry.roomID) entry.roomID = roomid; + if (!entry.time) entry.time = Date.now(); + if (entry.isGlobal && entry.roomID !== 'global' && !entry.roomID.startsWith('global-')) { + entry.roomID = `global-${entry.roomID}`; + } + if (overrideID) entry.visualRoomID = overrideID; + + const entries = [entry]; + if (Config.usesqlitemodlog) this.writeSQL(entries); + this.writeText(entries); + } + + writeSQL(entries: Iterable) { + this.insertionTransaction(entries); + } + + writeText(entries: Iterable) { + const buffers = new Map(); + for (const entry of entries) { + const streamID = entry.roomID as ModlogID; + let buf = buffers.get(streamID) || ''; + buf += `[${new Date(entry.time!).toJSON()}] (${entry.visualRoomID || entry.roomID}) ${entry.action}:`; + if (entry.userid) buf += ` [${entry.userid}]`; + if (entry.autoconfirmedID) buf += ` ac:[${entry.autoconfirmedID}]`; + if (entry.alts) buf += ` alts:[${entry.alts.join('], [')}]`; + if (entry.ip) buf += ` [${entry.ip}]`; + if (entry.loggedBy) buf += ` by ${entry.loggedBy}`; + if (entry.note) buf += `: ${entry.note}`; + buf += `\n`; + buffers.set(streamID, buf); + } + + for (const [streamID, buffer] of buffers) { + const stream = this.streams.get(streamID); + if (!stream) throw new Error(`Attempted to write to an uninitialized modlog stream for the room '${streamID}'`); + void stream.write(buffer); + } } async destroy(roomid: ModlogID) { @@ -185,12 +289,18 @@ export class Modlog { } async rename(oldID: ModlogID, newID: ModlogID) { + if (oldID === newID) return; + + // rename flat-file modlogs const streamExists = this.streams.has(oldID); if (streamExists) await this.destroy(oldID); if (!this.getSharedID(oldID)) { await FS(`${this.logPath}/modlog_${oldID}.txt`).rename(`${this.logPath}/modlog_${newID}.txt`); } if (streamExists) this.initialize(newID); + + // rename SQL modlogs + this.runSQL({statement: this.renameQuery, args: [newID, oldID]}); } getActiveStreamIDs() { @@ -200,7 +310,7 @@ export class Modlog { /****************************************** * Methods for reading (searching) modlog * ******************************************/ - async runSearch( + async runTextSearch( rooms: ModlogID[], regexString: string, maxLines: number, onlyPunishments: boolean | string ) { const useRipgrep = await checkRipgrepAvailability(); @@ -260,33 +370,24 @@ export class Modlog { } async getGlobalPunishments(user: User | string, days = 30) { + return this.getGlobalPunishmentsText(toID(user), days); + } + + async getGlobalPunishmentsText(userid: ID, days: number) { const response = await PM.query({ rooms: ['global' as ModlogID], - regexString: this.escapeRegex(`[${toID(user)}]`), + regexString: this.escapeRegex(`[${userid}]`), maxLines: days * 10, onlyPunishments: 'global', }); return response.length; } - generateRegex(search: string) { - // Ensure the generated regex can never be greater than or equal to the value of - // RegExpMacroAssembler::kMaxRegister in v8 (currently 1 << 16 - 1) given a - // search with max length MAX_QUERY_LENGTH. Otherwise, the modlog - // child process will crash when attempting to execute any RegExp - // constructed with it (i.e. when not configured to use ripgrep). - return `[^a-zA-Z0-9]?${[...search].join('[^a-zA-Z0-9]*')}([^a-zA-Z0-9]|\\z)`; - } - - escapeRegex(search: string) { - return search.replace(/[\\.+*?()|[\]{}^$]/g, '\\$&'); - } - async search( roomid: ModlogID = 'global', search: ModlogSearch = {}, maxLines = 20, - onlyPunishments = false + onlyPunishments = false, ): Promise { const rooms = (roomid === 'public' ? [...Rooms.rooms.values()] @@ -294,6 +395,25 @@ export class Modlog { .map(room => room.roomid) : [roomid]); + const query = this.prepareSearch(rooms, maxLines, onlyPunishments, search); + const response = await PM.query(query); + + if (response.duration > LONG_QUERY_DURATION) { + Monitor.log(`Long modlog query took ${response.duration} ms to complete: ${JSON.stringify(query)}`); + } + return {results: response, duration: response.duration}; + } + + prepareSearch(rooms: ModlogID[], maxLines: number, onlyPunishments: boolean, search: ModlogSearch) { + return this.prepareTextSearch(rooms, maxLines, onlyPunishments, search); + } + + prepareTextSearch( + rooms: ModlogID[], + maxLines: number, + onlyPunishments: boolean, + search: ModlogSearch + ): ModlogTextQuery { // Ensure regexString can never be greater than or equal to the value of // RegExpMacroAssembler::kMaxRegister in v8 (currently 1 << 16 - 1) given a // searchString with max length MAX_QUERY_LENGTH. Otherwise, the modlog @@ -309,24 +429,18 @@ export class Modlog { if (search.ip) regexString += `${this.escapeRegex(`[${search.ip}`)}.*?\\].*?`; if (search.actionTaker) regexString += `${this.escapeRegex(`by ${search.actionTaker}`)}.*?`; if (search.note) { - const regexGenerator = search.note.isExact ? this.generateRegex : this.escapeRegex; + const regexGenerator = search.note.isExact ? this.generateIDRegex : this.escapeRegex; for (const noteSearch of search.note.searches) { regexString += `${regexGenerator(toID(noteSearch))}.*?`; } } - const query = { + return { rooms: rooms, regexString, maxLines: maxLines, onlyPunishments: onlyPunishments, }; - const response = await PM.query(query); - - if (response.duration > LONG_QUERY_DURATION) { - Monitor.log(`Long modlog query took ${response.duration} ms to complete: ${query}`); - } - return {results: response, duration: response.duration}; } private async readRoomModlog(path: string, results: SortedLimitedLengthList, regex?: RegExp) { @@ -346,10 +460,13 @@ export class Modlog { // even though it's a type not a function... type ModlogResult = ModlogEntry | undefined; -export const PM = new QueryProcessManager(module, async data => { + +// the ProcessManager only accepts text queries at this time +// SQL support is to be determined +export const PM = new QueryProcessManager(module, async data => { const {rooms, regexString, maxLines, onlyPunishments} = data; try { - const results = await modlog.runSearch(rooms, regexString, maxLines, onlyPunishments); + const results = await Rooms.Modlog.runTextSearch(rooms, regexString, maxLines, onlyPunishments); return results.map((line: string, index: number) => parseModlog(line, results[index + 1])); } catch (err) { Monitor.crashlog(err, 'A modlog query', data); @@ -361,6 +478,8 @@ if (!PM.isParentProcess) { global.Config = require('./config-loader').Config; global.toID = require('../sim/dex').Dex.toID; + global.Rooms = require('./rooms').Rooms; + global.Monitor = { crashlog(error: Error, source = 'A modlog process', details: AnyObject | null = null) { const repr = JSON.stringify([error.name, error.message, source, details]); @@ -379,5 +498,3 @@ if (!PM.isParentProcess) { } else { PM.spawn(MAX_PROCESSES); } - -export const modlog = new Modlog(MODLOG_PATH); diff --git a/server/rooms.ts b/server/rooms.ts index 786ba5831832..e28878a0d288 100644 --- a/server/rooms.ts +++ b/server/rooms.ts @@ -26,6 +26,9 @@ const LAST_BATTLE_WRITE_THROTTLE = 10; const RETRY_AFTER_LOGIN = null; +const MODLOG_PATH = 'logs/modlog'; +const MODLOG_DB_PATH = `${__dirname}/../databases/modlog.db`; + import {FS} from '../lib/fs'; import {Utils} from '../lib/utils'; import {WriteStream} from '../lib/streams'; @@ -38,7 +41,7 @@ import {RoomGame, RoomGamePlayer} from './room-game'; import {Roomlogs} from './roomlogs'; import * as crypto from 'crypto'; import {RoomAuth} from './user-groups'; -import {modlog, ModlogEntry} from './modlog'; +import {Modlog, ModlogEntry} from './modlog'; /********************************************************* * the Room object. @@ -1672,7 +1675,9 @@ function getRoom(roomid?: string | BasicRoom) { } export const Rooms = { - Modlog: modlog, + MODLOG_PATH, + MODLOG_DB_PATH, + Modlog: new Modlog(MODLOG_PATH, MODLOG_DB_PATH), /** * The main roomid:Room table. Please do not hold a reference to a * room long-term; just store the roomid and grab it from here (with diff --git a/test/server/modlog.js b/test/server/modlog.js index cd01b9c3f7b0..212e1c296dfb 100644 --- a/test/server/modlog.js +++ b/test/server/modlog.js @@ -5,49 +5,57 @@ 'use strict'; -const TEST_PATH = 'test/modlogs'; - -const {FS} = require('../../.lib-dist/fs'); - const ml = require('../../.server-dist/modlog'); -const modlog = new ml.Modlog(TEST_PATH); +const modlog = new ml.Modlog('/dev/null', ':memory:'); const assert = require('assert').strict; +Config.usesqlitemodlog = true; + const DATASET_A = [ - `[2020-07-29T23:29:49.707Z] (readingtest) ROOMBAN: sometroll [127.0.0.1] by annika (FIRST ENTRY)`, - `[2020-07-29T23:29:49.717Z] (readingtest) LOCK: sometroll [127.0.0.1] by annika (ENTRY 2)`, - `[2020-07-29T23:29:49.72Z] (readingtest) ROOMBAN: sometroll [127.0.0.1] by annika (ENTRY 3)`, - `[2020-07-29T23:29:49.737Z] (readingtest) WEEKLOCK: sometroll [127.0.0.1] by annika (ENTRY 4)`, - `[2020-07-29T23:29:49.747Z] (readingtest) ROOMBAN: sometroll [127.0.0.1] by annika (ENTRY 5)`, - `[2020-07-29T23:29:49.757Z] (readingtest) ROOMBAN: sometroll [127.0.0.1] by annika (ENTRY 6)`, - `[2020-07-29T23:29:49.767Z] (readingtest) MUTE: sometroll [127.0.0.1] by annika (ENTRY 7)`, - `[2020-07-29T23:29:49.777Z] (readingtest) ROOMBAN: sometroll [127.0.0.1] by annika (ENTRY 8)`, - `[2020-07-29T23:29:49.787Z] (readingtest) ROOMBAN: sometroll [127.0.0.1] by annika (LAST ENTRY)`, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'FIRST ENTRY', time: 1}, + {action: 'LOCK', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'ENTRY 2', time: 2}, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'ENTRY 3', time: 3}, + {action: 'WEEKLOCK', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'this entry has many parts', time: 4}, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'ENTRY 5', time: 5}, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'ENTRY 6', time: 6}, + {action: 'MUTE', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'ENTRY 7', time: 7}, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'ENTRY 8', time: 8}, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika', note: 'LAST ENTRY', time: 9}, ]; const DATASET_B = [ - `[2020-07-29T23:29:49.797Z] (readingtest2) ROOMBAN: sometroll [127.0.0.1] by annika`, - `[2020-07-29T23:29:49.807Z] (readingtest2) ROOMBAN: sometroll [127.0.0.1] by annika`, - `[2020-07-29T23:29:49.817Z] (readingtest2) POLL: by annika`, - `[2020-07-29T23:29:49.827Z] (readingtest2) ROOMBAN: sometroll [127.0.0.1] by annika`, - `[2020-07-29T23:29:49.837Z] (readingtest2) TOUR START: by annika`, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika'}, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika'}, + {action: 'POLL', loggedBy: 'annika'}, + {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', loggedBy: 'annika'}, + {action: 'TOUR START', loggedBy: 'annika'}, ]; -/** - * Normalizes a modlog entry, handling timestamps and the like. - */ -const normalizeModlogEntry = (entry) => entry.replace(/\[[^\]]+\]/, `[TIMESTAMP]`); - -async function getLines(roomid) { - const lines = (await FS(`${TEST_PATH}/modlog_${modlog.getSharedID(roomid) || roomid}.txt`).read()).split('\n'); - let lastLine; - while (!lastLine) lastLine = lines.pop(); - if (!lastLine) throw new Error(`No modlog lines written.`); - return {lastLine, lines}; +function lastLine(database, roomid) { + return database.prepare( + `SELECT * FROM modlog WHERE roomid = ? ORDER BY modlog_id DESC LIMIT 1` + ).get(roomid); } -describe('Modlog (without FS writes)', () => { - it('should correctly determine if a room has a shared modlog', () => { +describe('Modlog', () => { + describe.skip('Modlog#prepareSQLSearch', () => { + it('should respect the maxLines parameter', () => { + const query = modlog.prepareSQLSearch(['lobby'], 1337, false, {}); + assert(query.statement.source.endsWith('LIMIT ?')); + assert(query.args.includes(1337)); + + const noMaxLines = modlog.prepareSQLSearch(['lobby'], 0, false, {}).statement; + assert(!noMaxLines.source.toUpperCase().includes('LIMIT')); + }); + + it('should attempt to respect onlyPunishments', () => { + const query = modlog.prepareSQLSearch(['lobby'], 0, true, {}); + assert(query.statement.source.includes('action IN (')); + assert(query.args.includes('WEEKLOCK')); + }); + }); + + describe('Modlog#getSharedID', () => { assert(modlog.getSharedID('battle-gen8randombattle-42')); assert(modlog.getSharedID('groupchat-annika-shitposting')); assert(modlog.getSharedID('help-mePleaseIAmTrappedInAUnitTestFactory')); @@ -56,171 +64,139 @@ describe('Modlog (without FS writes)', () => { assert(!modlog.getSharedID('development')); }); - it('should throw an error when writing to a destroyed modlog stream', () => { - modlog.initialize('somedeletedroom'); - assert.doesNotThrow(() => modlog.write('somedeletedroom', 'ROOMBAN: sometroll [127.0.0.1] by annika')); - modlog.destroy('somedeletedroom'); - assert.throws(() => modlog.write('somedeletedroom', 'ROOMBAN: sometroll [127.0.0.1] by annika')); + describe('Modlog#write', () => { + it('should write messages serially to the modlog', async () => { + modlog.initialize('development'); + modlog.write('development', {note: 'This message is logged first', action: 'UNITTEST'}); + modlog.write('development', {note: 'This message is logged second', action: 'UNITTEST'}); + const lines = modlog.database.prepare( + // Order by modlog_id since the writes most likely happen at the same second + `SELECT * FROM modlog WHERE roomid = 'development' ORDER BY modlog_id DESC LIMIT 2` + ).all(); + + assert.equal(lines.pop().note, 'This message is logged first'); + assert.equal(lines.pop().note, 'This message is logged second'); + }); + + it('should throw an error when writing to a destroyed modlog stream', () => { + modlog.initialize('somedeletedroom'); + assert.doesNotThrow(() => modlog.write('somedeletedroom', {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', staff: 'annika'})); + modlog.destroy('somedeletedroom'); + assert.throws(() => modlog.write('somedeletedroom', {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', staff: 'annika'})); + }); + + it('should throw an error when writing to an uninitialized modlog stream', () => { + assert.throws(() => modlog.write('lmaothisroomisntreal', {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', staff: 'annika'})); + modlog.initialize('itsrealnow'); + assert.doesNotThrow(() => modlog.write('itsrealnow', {action: 'ROOMBAN', userid: 'sometroll', ip: '127.0.0.1', staff: 'annika'})); + }); + + + it('should use overrideID if specified', async () => { + modlog.initialize('battle-gen8randombattle-1337'); + modlog.write('battle-gen8randombattle-1337', {note: "I'm testing overrideID", action: 'UNITTEST'}, 'heyadora'); + const line = lastLine(modlog.database, 'battle-gen8randombattle-1337'); + assert.equal(line.note, "I'm testing overrideID"); + assert.equal(line.visual_roomid, 'heyadora'); + }); }); - it('should throw an error when writing to an uninitialized modlog stream', () => { - assert.throws(() => modlog.write('lmaothisroomisntreal', 'ROOMBAN: sometroll [127.0.0.1] by annika')); - modlog.initialize('itsrealnow'); - assert.doesNotThrow(() => modlog.write('itsrealnow', 'ROOMBAN: sometroll [127.0.0.1] by annika')); - }); -}); - -describe.skip('Modlog (with FS writes)', () => { - before(async () => { - /** - * Some modlog tests involve writing to the filesystem. - * Filesystem writes are disabled again in after(), - * so this only affects tests in this describe(). - */ - Config.nofswriting = false; - - await FS(TEST_PATH).mkdirp(); - await FS(`${TEST_PATH}/modlog_readingtest.txt`).write(DATASET_A.join('\n') + '\n'); - await FS(`${TEST_PATH}/modlog_readingtest2.txt`).write(DATASET_B.join('\n') + '\n'); - }); + describe("Modlog#rename", async () => { + const entry = {note: 'This is in a modlog that will be renamed!', action: 'UNITTEST'}; - after(async () => { - // This currently fails on Windows; it fails to remove - // the directory and crashes as a result - await FS(TEST_PATH).rmdir(true); - Config.nofswriting = true; - }); - - /******************************* - * Tests for writing to modlog * - *******************************/ - it('should write messages serially to the modlog', async () => { - modlog.initialize('development'); - modlog.write('development', 'ROOMOWNER: [somecooluser] by someadmin'); - modlog.write('development', 'ROOMBAN: [kjnhvgcfg] [127.0.0.1] by annika'); - await modlog.destroy('development'); // ensure all writes have synced to disk - - const lines = await getLines('development'); - - assert.equal( - normalizeModlogEntry(lines.lastLine), - normalizeModlogEntry('[2020-07-29T23:29:49.797Z] (development) ROOMBAN: [kjnhvgcfg] [127.0.0.1] by annika') - ); - assert.equal( - normalizeModlogEntry(lines.lines.pop()), - normalizeModlogEntry('[2020-07-29T23:29:49.797Z] (development) ROOMOWNER: [somecooluser] by someadmin') - ); - }); - - it('should support renaming modlogs', async () => { - const message = 'ROOMREGULAR USER: [somerandomreg] by annika (demote)'; - // Modlog renaming tests should pass whether or not the room names within the file are changed - const messageRegex = /\[[^\]]+\] \((oldroom|newroom)\) ROOMREGULAR USER: \[somerandomreg\] by annika \(demote\)/; modlog.initialize('oldroom'); - modlog.write('oldroom', message); + modlog.write('oldroom', entry); await modlog.rename('oldroom', 'newroom'); + const line = lastLine(modlog.database, 'newroom'); - assert(FS(`${TEST_PATH}/modlog_newroom.txt`).existsSync()); - assert.throws(() => modlog.write('oldroom', 'something')); - - let lastLine = (await getLines('newroom')).lastLine; - assert(messageRegex.test(lastLine)); + assert.equal(entry.action, line.action); + assert.equal(entry.note, line.note); - modlog.write('newroom', 'ROOMBAN: [kjnhvgcfg] [127.0.0.1] by annika'); - await modlog.destroy('newroom'); // ensure all writes have synced to disk + const newEntry = {note: 'This modlog has been renamed!', action: 'UNITTEST'}; + modlog.write('newroom', newEntry); - lastLine = (await getLines('newroom')).lastLine; - assert.equal( - normalizeModlogEntry(lastLine), - normalizeModlogEntry('[2020-07-29T23:29:49.797Z] (newroom) ROOMBAN: [kjnhvgcfg] [127.0.0.1] by annika') - ); - }); - - it('should use overrideID if specified', async () => { - modlog.initialize('battle-gen8randombattle-1337'); - modlog.write('battle-gen8randombattle-1337', 'MODCHAT: by annika: to +', 'actually this: cool name'); - await modlog.destroy('battle-gen8randombattle-1337'); // ensure all writes have synced to disk + const newLine = lastLine(modlog.database, 'newroom'); - const lastLine = (await getLines('battle-gen8randombattle-1337')).lastLine; - assert.equal( - normalizeModlogEntry(lastLine), - normalizeModlogEntry('[2020-07-29T23:29:49.797Z] (actually this: cool name) MODCHAT: by annika: to +') - ); + assert.equal(newEntry.action, newLine.action); + assert.equal(newEntry.note, newLine.note); }); - /************************************** - * Tests for reading/searching modlog * - **************************************/ - it('should read the entire modlog file when not limited', async () => { - const results = await modlog.runSearch(['readingtest'], '', false, 10000, false); - assert.equal(results.length, DATASET_A.length); - }); - - it("should support searching multiple rooms' modlogs", async () => { - const results = await modlog.runSearch(['readingtest', 'readingtest2'], '', false, 10000, false); - assert.equal(results.length, DATASET_A.length + DATASET_B.length); - }); - - it('should be case-insensitive', async () => { - const notExactUpper = await modlog.runSearch(['readingtest'], 'someTRoll', false, 10000, false); - const notExactLower = await modlog.runSearch(['readingtest'], 'someTRoll', false, 10000, false); - const exactUpper = await modlog.runSearch(['readingtest'], 'sOmEtRoLl', true, 10000, false); - const exactLower = await modlog.runSearch(['readingtest'], 'sOmEtRoLl', true, 10000, false); - - assert.deepEqual(notExactUpper, notExactLower); - assert.deepEqual(exactUpper, exactLower); - }); - - it('should respect isExact', async () => { - const notExact = await modlog.runSearch(['readingtest'], 'troll', false, 10000, false); - const exact = await modlog.runSearch(['readingtest'], 'troll', true, 10000, false); - - assert.equal(notExact.length, 0); - assert(exact.length); - }); - - it('should be LIFO (last-in, first-out)', async () => { - modlog.initialize('lifotest'); - modlog.write('lifotest', 'firstwrite'); - modlog.write('lifotest', 'secondwrite'); - await modlog.destroy('lifotest'); - - const search = await modlog.runSearch(['lifotest'], '', false, 10000, false); - - assert.equal(search.length, 2); - - assert(search[0].includes('secondwrite')); - assert(!search[0].includes('firstwrite')); - - assert(search[1].includes('firstwrite')); - assert(!search[1].includes('secondwrite')); - }); - - it('should support limiting the number of responses', async () => { - const unlimited = await modlog.runSearch(['readingtest'], '', false, 10000, false); - const limited = await modlog.runSearch(['readingtest'], '', false, 5, false); - - assert.equal(limited.length, 5); - assert(unlimited.length > limited.length); - - assert(limited[0].includes('LAST ENTRY')); - assert(unlimited[0].includes('LAST ENTRY')); - - const limitedLast = limited.pop(); - const unlimitedLast = unlimited.pop(); - - assert(!limitedLast.includes('FIRST ENTRY')); - assert(unlimitedLast.includes('FIRST ENTRY')); - }); - - it('should support filtering out non-punishment-related logs', async () => { - const all = await modlog.runSearch(['readingtest2'], '', false, 10000, false); - const onlyPunishments = await modlog.runSearch(['readingtest2'], '', false, 10000, true); - - assert(all.length > onlyPunishments.length); - assert.equal( - onlyPunishments.filter(result => result.includes('ROOMBAN')).length, - onlyPunishments.length - ); + // Skipped until SQL searching is properly implemented + describe.skip('Modlog#search', () => { + before(async () => { + modlog.initialize('readingtest'); + modlog.initialize('readingtest2'); + for (const entry of DATASET_A) { + modlog.write('readingtest', entry); + } + for (const entry of DATASET_B) { + modlog.write('readingtest2', entry); + } + }); + + it('should be capable of reading the entire modlog file', async () => { + const results = await modlog.search('readingtest2', {}, 10000); + assert.equal(results.results.length, DATASET_B.length); + }); + + it('user searches should be case-insensitive', async () => { + const notExactUpper = await modlog.search('readingtest', {user: {search: 'sOmETRoll', isExact: false}}); + const notExactLower = await modlog.search('readingtest', {user: {search: 'sometroll', isExact: false}}); + const exactUpper = await modlog.search('readingtest', {user: {search: 'sOMEtroLL', isExact: true}}); + const exactLower = await modlog.search('readingtest', {user: {search: 'sometroll', isExact: true}}); + + assert.deepEqual(notExactUpper.results, notExactLower.results); + assert.deepEqual(exactUpper.results, exactLower.results); + }); + + it('note searches should respect isExact', async () => { + const notExact = await modlog.search('readingtest', {note: {searches: ['has man'], isExact: false}}); + const exact = await modlog.search('readingtest', {note: {searches: ['has man'], isExact: true}}); + assert.equal(notExact.results.length, 0); + assert(exact.results.length); + }); + + it.skip('should be LIFO (last-in, first-out)', async () => { + modlog.initialize('lifotest'); + + modlog.write('lifotest', {note: 'firstwrite', action: 'UNITTEST', timestamp: 1}); + modlog.write('lifotest', {note: 'secondwrite', action: 'UNITTEST', timestamp: 2}); + const search = await modlog.search('lifotest'); + assert.equal(search.results.length, 2); + + assert(search.results[0].note !== 'secondwrite'); + assert(search.results[0].note === 'firstwrite'); + + assert(search.results[1].note !== 'firstwrite'); + assert(search.results[1].note === 'secondwrite'); + }); + + it('should support limiting the number of responses', async () => { + const unlimited = await modlog.search('readingtest'); + const limited = await modlog.search('readingtest', {}, 5); + + assert.equal(limited.results.length, 5); + assert(unlimited.results.length > limited.results.length); + + assert(limited.results[0].note.includes('LAST ENTRY')); + assert(unlimited.results[0].note.includes('LAST ENTRY')); + + const limitedLast = limited.results.pop().note; + const unlimitedLast = unlimited.results.pop().note; + + assert(!limitedLast.includes('FIRST ENTRY')); + assert(unlimitedLast.includes('FIRST ENTRY')); + }); + + it('should support filtering out non-punishment-related logs', async () => { + const all = (await modlog.search('readingtest2', {}, 20, false)).results; + const onlyPunishments = (await modlog.search('readingtest2', {}, 20, true)).results; + + assert(all.length > onlyPunishments.length); + assert.equal( + onlyPunishments.filter(result => result.action === 'ROOMBAN').length, + onlyPunishments.length + ); + }); }); }); diff --git a/test/tools/modlog/converter.js b/test/tools/modlog/converter.js index db624c659c0b..1cb2f2621040 100644 --- a/test/tools/modlog/converter.js +++ b/test/tools/modlog/converter.js @@ -611,9 +611,11 @@ describe('Modlog conversion script', () => { describe.skip('integration tests', () => { it('should convert from SQLite to text', async () => { - const modlog = new ml.Modlog(':memory:', true); + const modlog = new ml.Modlog('/dev/null', ':memory:', true); const mlConverter = new converter.ModlogConverterSQLite('', '', modlog.database); + modlog.initialize('development'); + const entry = { action: 'UNITTEST', roomID: 'development', diff --git a/tools/modlog/convert b/tools/modlog/convert index 03a77f467dde..aaeac12fa485 100755 --- a/tools/modlog/convert +++ b/tools/modlog/convert @@ -42,4 +42,4 @@ if ( } console.log(`Converting ${from === 'txt' ? `the text modlog files in ${textLogPath}` : `${databasePath}`} from ${from} to ${to}...`); -ModlogConverter.convert(from, to, path.resolve(databasePath || ""), path.resolve(textLogPath), path.resolve(outputLogPath)); +ModlogConverter.convert(from, to, path.resolve(databasePath || ""), path.resolve(textLogPath), path.resolve(outputLogPath || "")); diff --git a/tools/modlog/converter.ts b/tools/modlog/converter.ts index 2098cb83a304..e63893aa9764 100644 --- a/tools/modlog/converter.ts +++ b/tools/modlog/converter.ts @@ -6,16 +6,18 @@ */ // @ts-ignore Needed for FS -if (!global.Config) global.Config = {nofswriting: false}; +if (!global.Config) global.Config = {nofswriting: false, modlogftsextension: true, usesqlitemodlog: true}; + +import * as Database from 'better-sqlite3'; import {FS} from '../../lib/fs'; -import {ModlogEntry} from '../../server/modlog'; +import {Modlog, ModlogEntry} from '../../server/modlog'; import {IPTools} from '../../server/ip-tools'; -type ModlogFormat = 'txt'; +type ModlogFormat = 'txt' | 'sqlite'; /** The number of modlog entries to write to the database on each transaction */ -const ENTRIES_TO_BUFFER = 100; +const ENTRIES_TO_BUFFER = 25000; const IP_ONLY_ACTIONS = new Set([ 'SHAREDIP', 'UNSHAREDIP', 'UNLOCKIP', 'UNLOCKRANGE', 'RANGEBAN', 'RANGELOCK', @@ -344,7 +346,7 @@ export function parseModlog(raw: string, nextLine?: string, isGlobal = false): M const log: ModlogEntry = {action: 'NULL', isGlobal}; const timestamp = parseBrackets(line, '['); - log.time = Math.floor(new Date(timestamp).getTime()); + log.time = Math.floor(new Date(timestamp).getTime()) || Date.now(); line = line.slice(timestamp.length + 3); const [roomid, ...bonus] = parseBrackets(line, '(').split(' '); @@ -434,12 +436,166 @@ export function rawifyLog(log: ModlogEntry) { if (log.userid) result += `: [${log.userid}]`; if (log.autoconfirmedID) result += ` ac: [${log.autoconfirmedID}]`; if (log.alts) result += ` alts: [${log.alts.join('], [')}]`; - if (log.ip) result += ` [${log.ip}]`; + if (log.ip) { + if (!log.userid) result += `:`; + result += ` [${log.ip}]`; + } if (log.loggedBy) result += `${result.endsWith(']') ? '' : ':'} by ${log.loggedBy}`; if (log.note) result += `: ${log.note}`; return result + `\n`; } +export class ModlogConverterSQLite { + readonly databaseFile: string; + readonly textLogDir: string; + readonly isTesting: {files: Map, db: Database.Database} | null = null; + + constructor(databaseFile: string, textLogDir: string, isTesting?: Database.Database) { + this.databaseFile = databaseFile; + this.textLogDir = textLogDir; + if (isTesting || Config.nofswriting) { + this.isTesting = {files: new Map(), db: isTesting || new Database(':memory:')}; + } + } + + async toTxt() { + const database = this.isTesting?.db || new Database(this.databaseFile, {fileMustExist: true}); + const roomids = database.prepare('SELECT DISTINCT roomid FROM modlog').all(); + const globalEntries = []; + for (const {roomid} of roomids) { + if (!Config.nofswriting) console.log(`Reading ${roomid}...`); + const results = database.prepare( + `SELECT *, (SELECT group_concat(userid, ',') FROM alts WHERE alts.modlog_id = modlog.modlog_id) as alts ` + + `FROM modlog WHERE roomid = ? ORDER BY timestamp ASC` + ).all(roomid); + + const trueRoomID = roomid.replace(/^global-/, ''); + + let entriesLogged = 0; + let entries: string[] = []; + + const insertEntries = async () => { + if (roomid === 'global') return; + entriesLogged += entries.length; + if (!Config.nofswriting && (entriesLogged % ENTRIES_TO_BUFFER === 0 || entriesLogged < ENTRIES_TO_BUFFER)) { + process.stdout.clearLine(0); + process.stdout.cursorTo(0); + process.stdout.write(`Wrote ${entriesLogged} entries from '${trueRoomID}'`); + } + await this.writeFile(`${this.textLogDir}/modlog_${trueRoomID}.txt`, entries.join('')); + entries = []; + }; + + for (const result of results) { + const entry: ModlogEntry = { + action: result.action, + roomID: result.roomid?.replace(/^global-/, ''), + visualRoomID: result.visual_roomid, + userid: result.userid, + autoconfirmedID: result.autoconfirmed_userid, + alts: result.alts?.split(','), + ip: result.ip, + isGlobal: result.roomid?.startsWith('global-') || result.roomid === 'global', + loggedBy: result.action_taker_userid, + note: result.note, + time: result.timestamp, + }; + + const rawLog = rawifyLog(entry); + entries.push(rawLog); + if (entry.isGlobal) { + globalEntries.push(rawLog); + } + if (entries.length === ENTRIES_TO_BUFFER) await insertEntries(); + } + await insertEntries(); + if (entriesLogged) process.stdout.write('\n'); + } + if (!Config.nofswriting) console.log(`Writing the global modlog...`); + await this.writeFile(`${this.textLogDir}/modlog_global.txt`, globalEntries.join('')); + } + + async writeFile(path: string, text: string) { + if (this.isTesting) { + const old = this.isTesting.files.get(path); + return this.isTesting.files.set(path, `${old || ''}${text}`); + } + return FS(path).append(text); + } +} + +export class ModlogConverterTxt { + readonly databaseFile: string; + readonly modlog: Modlog; + + readonly textLogDir: string; + readonly isTesting: {files: Map, ml?: Modlog} | null = null; + constructor(databaseFile: string, textLogDir: string, isTesting?: Map, useFTSExtension?: boolean) { + this.databaseFile = databaseFile; + this.textLogDir = textLogDir; + if (isTesting || Config.nofswriting) { + this.isTesting = { + files: isTesting || new Map(), + }; + } + + this.modlog = new Modlog(this.textLogDir, this.isTesting ? ':memory:' : this.databaseFile); + } + + async toSQLite() { + const files = this.isTesting ? [...this.isTesting.files.keys()] : await FS(this.textLogDir).readdir(); + // Read global modlog last to avoid inserting duplicate data to database + if (files.includes('modlog_global.txt')) { + files.splice(files.indexOf('modlog_global.txt'), 1); + files.push('modlog_global.txt'); + } + + const globalEntries = []; + + for (const file of files) { + if (file === 'README.md') continue; + const roomid = file.slice(7, -4); + const lines = this.isTesting ? + this.isTesting.files.get(file)?.split('\n') || [] : + FS(`${this.textLogDir}/${file}`).createReadStream().byLine(); + + let entriesLogged = 0; + let lastLine = undefined; + let entries: ModlogEntry[] = []; + + + const insertEntries = (alwaysShowProgress?: boolean) => { + this.modlog.writeSQL(entries); + entriesLogged += entries.length; + if (!Config.nofswriting && ( + alwaysShowProgress || + entriesLogged % ENTRIES_TO_BUFFER === 0 || + entriesLogged < ENTRIES_TO_BUFFER + )) { + process.stdout.clearLine(0); + process.stdout.cursorTo(0); + process.stdout.write(`Inserted ${entriesLogged} entries from '${roomid}'`); + } + entries = []; + }; + + for await (const line of lines) { + const entry = parseModlog(line, lastLine, roomid === 'global'); + lastLine = line; + if (!entry) continue; + if (roomid !== 'global') entries.push(entry); + if (entry.isGlobal) { + globalEntries.push(entry); + } + if (entries.length === ENTRIES_TO_BUFFER) insertEntries(); + } + insertEntries(true); + if (entriesLogged) process.stdout.write('\n'); + } + return this.modlog.database; + } +} + export class ModlogConverterTest { readonly inputDir: string; readonly outputDir: string; @@ -510,6 +666,16 @@ export const ModlogConverter = { await converter.toTxt(); console.log("\nDone!"); process.exit(); + } else if (from === 'sqlite' && to === 'txt') { + const converter = new ModlogConverterSQLite(databasePath, textLogDirectoryPath); + await converter.toTxt(); + console.log("\nDone!"); + process.exit(); + } else if (from === 'txt' && to === 'sqlite') { + const converter = new ModlogConverterTxt(databasePath, textLogDirectoryPath); + await converter.toSQLite(); + console.log("\nDone!"); + process.exit(); } }, };