diff --git a/std/log/README.md b/std/log/README.md index 55b2b6cdb3..4c69784f99 100644 --- a/std/log/README.md +++ b/std/log/README.md @@ -107,7 +107,10 @@ interface HandlerOptions { #### `FileHandler` This handler will output to a file using an optional mode (default is `a`, e.g. -append). The file will grow indefinitely. This logger takes `FileOptions`: +append). The file will grow indefinitely. It uses a buffer for writing to file +and will automatically flush every 30 seconds, though you can trigger this +yourself with `fileHandler.flush()`. Log messages with a log level greater than +error are immediately flushed. This logger takes `FileOptions`: ```typescript interface FileHandlerOptions { @@ -148,6 +151,11 @@ backups to keep), `log.txt.1` would be renamed to `log.txt.2`, `log.txt` would be renamed to `log.txt.1` and finally `log.txt` would be created from scratch where the new log message would be written. +This handler uses a buffer for writing to file and will automatically flush +every 30 seconds, though you can trigger this yourself with +`fileHandler.flush()`. Log messages with a log level greater than error are +immediately flushed. + Options for this handler are: ```typescript diff --git a/std/log/handlers.ts b/std/log/handlers.ts index 3c8dd68969..b7a8c9cae2 100644 --- a/std/log/handlers.ts +++ b/std/log/handlers.ts @@ -7,6 +7,7 @@ import { getLevelByName, LevelName, LogLevels } from "./levels.ts"; import { LogRecord } from "./logger.ts"; import { red, yellow, blue, bold } from "../fmt/colors.ts"; import { existsSync, exists } from "../fs/exists.ts"; +import { BufWriterSync } from "../io/bufio.ts"; const DEFAULT_FORMATTER = "{levelName} {msg}"; type FormatterFunction = (logRecord: LogRecord) => string; @@ -99,11 +100,14 @@ interface FileHandlerOptions extends HandlerOptions { } export class FileHandler extends WriterHandler { - protected _file!: File; + protected _file: File | undefined; + protected _buf!: BufWriterSync; protected _filename: string; protected _mode: LogMode; protected _openOptions: OpenOptions; - #encoder = new TextEncoder(); + protected _encoder = new TextEncoder(); + #intervalId = -1; + #unloadCallback = (): Promise => this.destroy(); constructor(levelName: LevelName, options: FileHandlerOptions) { super(levelName, options); @@ -122,14 +126,39 @@ export class FileHandler extends WriterHandler { async setup(): Promise { this._file = await open(this._filename, this._openOptions); this._writer = this._file; + this._buf = new BufWriterSync(this._file); + + addEventListener("unload", this.#unloadCallback); + + // flush the buffer every 30 seconds + this.#intervalId = setInterval(() => this.flush(), 30 * 1000); + } + + handle(logRecord: LogRecord): void { + super.handle(logRecord); + + // Immediately flush if log level is higher than ERROR + if (logRecord.level > LogLevels.ERROR) { + this.flush(); + } } log(msg: string): void { - Deno.writeAllSync(this._file, this.#encoder.encode(msg + "\n")); + this._buf.writeSync(this._encoder.encode(msg + "\n")); + } + + flush(): void { + if (this._buf?.buffered() > 0) { + this._buf.flush(); + } } destroy(): Promise { - this._file.close(); + this.flush(); + this._file?.close(); + this._file = undefined; + removeEventListener("unload", this.#unloadCallback); + clearInterval(this.#intervalId); return Promise.resolve(); } } @@ -143,7 +172,6 @@ export class RotatingFileHandler extends FileHandler { #maxBytes: number; #maxBackupCount: number; #currentFileSize = 0; - #encoder = new TextEncoder(); constructor(levelName: LevelName, options: RotatingFileHandlerOptions) { super(levelName, options); @@ -153,9 +181,11 @@ export class RotatingFileHandler extends FileHandler { async setup(): Promise { if (this.#maxBytes < 1) { + this.destroy(); throw new Error("maxBytes cannot be less than 1"); } if (this.#maxBackupCount < 1) { + this.destroy(); throw new Error("maxBackupCount cannot be less than 1"); } await super.setup(); @@ -172,7 +202,7 @@ export class RotatingFileHandler extends FileHandler { // Throw if any backups also exist for (let i = 1; i <= this.#maxBackupCount; i++) { if (await exists(this._filename + "." + i)) { - Deno.close(this._file.rid); + this.destroy(); throw new Deno.errors.AlreadyExists( "Backup log file " + this._filename + "." + i + " already exists" ); @@ -183,23 +213,21 @@ export class RotatingFileHandler extends FileHandler { } } - handle(logRecord: LogRecord): void { - if (this.level > logRecord.level) return; + log(msg: string): void { + const msgByteLength = this._encoder.encode(msg).byteLength + 1; - const msg = this.format(logRecord); - const msgByteLength = this.#encoder.encode(msg).byteLength + 1; if (this.#currentFileSize + msgByteLength > this.#maxBytes) { this.rotateLogFiles(); - this.#currentFileSize = msgByteLength; - } else { - this.#currentFileSize += msgByteLength; + this.#currentFileSize = 0; } - return this.log(msg); + this._buf.writeSync(this._encoder.encode(msg + "\n")); + this.#currentFileSize += msgByteLength; } rotateLogFiles(): void { - close(this._file.rid); + this._buf.flush(); + close(this._file!.rid); for (let i = this.#maxBackupCount - 1; i >= 0; i--) { const source = this._filename + (i === 0 ? "" : "." + i); @@ -212,5 +240,6 @@ export class RotatingFileHandler extends FileHandler { this._file = openSync(this._filename, this._openOptions); this._writer = this._file; + this._buf = new BufWriterSync(this._file); } } diff --git a/std/log/handlers_test.ts b/std/log/handlers_test.ts index 5275a5ca0d..cb73fa56fa 100644 --- a/std/log/handlers_test.ts +++ b/std/log/handlers_test.ts @@ -120,14 +120,18 @@ test({ test({ name: "FileHandler with mode 'x' will throw if log file already exists", async fn() { + const fileHandler = new FileHandler("WARNING", { + filename: LOG_FILE, + mode: "x", + }); + Deno.writeFileSync(LOG_FILE, new TextEncoder().encode("hello world")); + await assertThrowsAsync(async () => { - Deno.writeFileSync(LOG_FILE, new TextEncoder().encode("hello world")); - const fileHandler = new FileHandler("WARNING", { - filename: LOG_FILE, - mode: "x", - }); await fileHandler.setup(); }, Deno.errors.AlreadyExists); + + await fileHandler.destroy(); + Deno.removeSync(LOG_FILE); }, }); @@ -172,30 +176,32 @@ test({ name: "RotatingFileHandler with mode 'x' will throw if any log file already exists", async fn() { + Deno.writeFileSync( + LOG_FILE + ".3", + new TextEncoder().encode("hello world") + ); + const fileHandler = new RotatingFileHandler("WARNING", { + filename: LOG_FILE, + maxBytes: 50, + maxBackupCount: 3, + mode: "x", + }); await assertThrowsAsync( async () => { - Deno.writeFileSync( - LOG_FILE + ".3", - new TextEncoder().encode("hello world") - ); - const fileHandler = new RotatingFileHandler("WARNING", { - filename: LOG_FILE, - maxBytes: 50, - maxBackupCount: 3, - mode: "x", - }); await fileHandler.setup(); }, Deno.errors.AlreadyExists, "Backup log file " + LOG_FILE + ".3 already exists" ); + + fileHandler.destroy(); Deno.removeSync(LOG_FILE + ".3"); Deno.removeSync(LOG_FILE); }, }); test({ - name: "RotatingFileHandler with first rollover", + name: "RotatingFileHandler with first rollover, monitor step by step", async fn() { const fileHandler = new RotatingFileHandler("WARNING", { filename: LOG_FILE, @@ -206,16 +212,43 @@ test({ await fileHandler.setup(); fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); // 'ERROR AAA\n' = 10 bytes + fileHandler.flush(); assertEquals((await Deno.stat(LOG_FILE)).size, 10); fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); + fileHandler.flush(); assertEquals((await Deno.stat(LOG_FILE)).size, 20); fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); + fileHandler.flush(); // Rollover occurred. Log file now has 1 record, rollover file has the original 2 assertEquals((await Deno.stat(LOG_FILE)).size, 10); assertEquals((await Deno.stat(LOG_FILE + ".1")).size, 20); + await fileHandler.destroy(); + + Deno.removeSync(LOG_FILE); + Deno.removeSync(LOG_FILE + ".1"); + }, +}); + +test({ + name: "RotatingFileHandler with first rollover, check all at once", + async fn() { + const fileHandler = new RotatingFileHandler("WARNING", { + filename: LOG_FILE, + maxBytes: 25, + maxBackupCount: 3, + mode: "w", + }); + await fileHandler.setup(); + + fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); // 'ERROR AAA\n' = 10 bytes + fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); + fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); await fileHandler.destroy(); + assertEquals((await Deno.stat(LOG_FILE)).size, 10); + assertEquals((await Deno.stat(LOG_FILE + ".1")).size, 20); + Deno.removeSync(LOG_FILE); Deno.removeSync(LOG_FILE + ".1"); }, @@ -310,11 +343,29 @@ test({ }); test({ - name: "RotatingFileHandler fileSize equal to bytelength of message + 1", + name: "Window unload flushes buffer", + async fn() { + const fileHandler = new FileHandler("WARNING", { + filename: LOG_FILE, + mode: "w", + }); + await fileHandler.setup(); + fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); // 'ERROR AAA\n' = 10 bytes + + assertEquals((await Deno.stat(LOG_FILE)).size, 0); + dispatchEvent(new Event("unload")); + assertEquals((await Deno.stat(LOG_FILE)).size, 10); + + Deno.removeSync(LOG_FILE); + }, +}); + +test({ + name: "RotatingFileHandler: rotate on byte length, not msg length", async fn() { const fileHandler = new RotatingFileHandler("WARNING", { filename: LOG_FILE, - maxBytes: 100, + maxBytes: 7, maxBackupCount: 1, mode: "w", }); @@ -323,12 +374,47 @@ test({ const msg = "。"; const msgLength = msg.length; const msgByteLength = new TextEncoder().encode(msg).byteLength; - await fileHandler.log(msg); - const fileSzie = (await Deno.stat(LOG_FILE)).size; + assertNotEquals(msgLength, msgByteLength); + assertEquals(msgLength, 1); + assertEquals(msgByteLength, 3); - assertEquals(fileSzie, msgByteLength + 1); - assertNotEquals(fileSzie, msgLength); - assertNotEquals(fileSzie, msgLength + 1); + fileHandler.log(msg); // logs 4 bytes (including '\n') + fileHandler.log(msg); // max bytes is 7, but this would be 8. Rollover. + + await fileHandler.destroy(); + + const fileSize1 = (await Deno.stat(LOG_FILE)).size; + const fileSize2 = (await Deno.stat(LOG_FILE + ".1")).size; + + assertEquals(fileSize1, msgByteLength + 1); + assertEquals(fileSize2, msgByteLength + 1); + + Deno.removeSync(LOG_FILE); + Deno.removeSync(LOG_FILE + ".1"); + }, +}); + +test({ + name: "FileHandler: Critical logs trigger immediate flush", + async fn() { + const fileHandler = new FileHandler("WARNING", { + filename: LOG_FILE, + mode: "w", + }); + await fileHandler.setup(); + + fileHandler.handle(new LogRecord("AAA", [], LogLevels.ERROR)); + + // ERROR won't trigger immediate flush + const fileSize = (await Deno.stat(LOG_FILE)).size; + assertEquals(fileSize, 0); + + fileHandler.handle(new LogRecord("AAA", [], LogLevels.CRITICAL)); + + // CRITICAL will trigger immediate flush + const fileSize2 = (await Deno.stat(LOG_FILE)).size; + // ERROR record is 10 bytes, CRITICAL is 13 bytes + assertEquals(fileSize2, 23); await fileHandler.destroy(); Deno.removeSync(LOG_FILE);