diff --git a/std/log/README.md b/std/log/README.md index dea1e5fe7e..12a0899422 100644 --- a/std/log/README.md +++ b/std/log/README.md @@ -5,22 +5,23 @@ ```ts import * as log from "https://deno.land/std/log/mod.ts"; -// simple default logger, you can customize it -// by overriding logger and handler named "default" +// Simple default logger out of the box. You can customize it +// by overriding logger and handler named "default", or providing +// additional logger configurations log.debug("Hello world"); log.info("Hello world"); log.warning("Hello world"); log.error("Hello world"); log.critical("500 Internal server error"); -// custom configuration +// custom configuration with 2 loggers (the default and `tasks` loggers) await log.setup({ handlers: { console: new log.handlers.ConsoleHandler("DEBUG"), file: new log.handlers.FileHandler("WARNING", { filename: "./log.txt", - // you can change format of output message + // you can change format of output message using any keys in `LogRecord` formatter: "{levelName} {msg}", }), }, @@ -48,7 +49,7 @@ logger.warning("buzz"); // logs to both `console` and `file` handlers // get custom logger logger = log.getLogger("tasks"); -logger.debug("fizz"); // won't get output becase this logger has "ERROR" level +logger.debug("fizz"); // won't get output because this logger has "ERROR" level logger.error("buzz"); // log to `console` // if you try to use a logger that hasn't been configured @@ -62,9 +63,9 @@ unknownLogger.info("foobar"); // no-op ### Loggers -Loggers are objects that you interact with. When you use logger method it +Loggers are objects that you interact with. When you use a logger method it constructs a `LogRecord` and passes it down to its handlers for output. To -create custom loggers speficify them in `loggers` when calling `log.setup`. +create custom loggers, specify them in `loggers` when calling `log.setup`. #### `LogRecord` @@ -72,28 +73,107 @@ create custom loggers speficify them in `loggers` when calling `log.setup`. well some meta data that can be later used when formatting a message. ```ts -interface LogRecord { - msg: string; - args: any[]; - datetime: Date; - level: number; - levelName: string; +class LogRecord { + readonly msg: string; + readonly args: any[]; + readonly datetime: Date; + readonly level: number; + readonly levelName: string; } ``` ### Handlers -Handlers are responsible for actual output of log messages. When handler is -called by logger it firstly checks that `LogRecord`'s level is not lower than +Handlers are responsible for actual output of log messages. When a handler is +called by a logger, it firstly checks that `LogRecord`'s level is not lower than level of the handler. If level check passes, handlers formats log record into string and outputs it to target. -`log` module comes with two built-in handlers: +`log` module comes with three built-in handlers: -- `ConsoleHandler` - (default) -- `FileHandler` +#### `ConsoleHandler` -#### Custom message format +This is the default logger. It will output color coded log messages to the +console via `console.log()`. This logger takes `HandlerOptions`: + +```typescript +type FormatterFunction = (logRecord: LogRecord) => string; + +interface HandlerOptions { + formatter?: string | FormatterFunction; //see `Custom message format` below +} +``` + +#### `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`: + +```typescript +interface FileHandlerOptions { + formatter?: string | FormatterFunction; //see `Custom message format` below + filename: string; + mode?: LogMode; // 'a', 'w', 'x' +} +``` + +Behavior of the log modes is as follows: + +- `'a'` - Default mode. Appends new log messages to the end of an existing log + file, or create a new log file if none exists +- `'w'` - Upon creation of the handler, any existing log file will be removed + and a new one created. +- `'x'` - This will create a new log file and throw an error if one already + exists + +This handler requires `--allow-write` permission on the log file. + +#### `RotatingFileHandler` + +This handler extends the functionality of the `FileHandler` by "rotating" the +log file when it reaches a certain size. `maxBytes` specifies the maximum size +in bytes that the log file can grow to before rolling over to a new one. If the +size of the new log message plus the current log file size exceeds `maxBytes` +then a roll over is triggered. When a roll over occurs, before the log message +is written, the log file is renamed and appended with `.1`. If a `.1` version +already existed, it would have been renamed `.2` first and so on. The maximum +number of log files to keep is specified by `maxBackupCount`. After the renames +are complete the log message is written to the original, now blank, file. + +Example: Given `log.txt`, `log.txt.1`, `log.txt.2` and `log.txt.3`, a +`maxBackupCount` of 3 and a new log message which would cause `log.txt` to +exceed `maxBytes`, then `log.txt.2` would be renamed to `log.txt.3` (thereby +discarding the original contents of `log.txt.3` since 3 is the maximum number of +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. + +Options for this handler are: + +```typescript +interface RotatingFileHandlerOptions { + maxBytes: number; + maxBackupCount: number; + formatter?: string | FormatterFunction; //see `Custom message format` below + filename: string; + mode?: LogMode; // 'a', 'w', 'x' +} +``` + +Additional notes on `mode` as described above: + +- `'a'` Default mode. As above, this will pick up where the logs left off in + rotation, or create a new log file if it doesn't exist. +- `'w'` in addition to starting with a clean `filename`, this mode will also + cause any existing backups (up to `maxBackupCount`) to be deleted on setup + giving a fully clean slate. +- `'x'` requires that neither `filename`, nor any backups (up to + `maxBackupCount`), exist before setup + +This handler requires both `--allow-read` and `--allow-write` permissions on the +log files. + +### Custom message format If you want to override default format of message you can define `formatter` option for handler. It can be either simple string-based format that uses diff --git a/std/log/handlers.ts b/std/log/handlers.ts index 32b0525e73..eea7f32ffb 100644 --- a/std/log/handlers.ts +++ b/std/log/handlers.ts @@ -1,13 +1,15 @@ // Copyright 2018-2020 the Deno authors. All rights reserved. MIT license. -const { open } = Deno; +const { open, openSync, close, renameSync, statSync } = Deno; type File = Deno.File; type Writer = Deno.Writer; import { getLevelByName, LogLevel } from "./levels.ts"; import { LogRecord } from "./logger.ts"; import { red, yellow, blue, bold } from "../fmt/colors.ts"; +import { existsSync, exists } from "../fs/exists.ts"; const DEFAULT_FORMATTER = "{levelName} {msg}"; type FormatterFunction = (logRecord: LogRecord) => string; +type LogMode = "a" | "w" | "x"; interface HandlerOptions { formatter?: string | FormatterFunction; @@ -85,33 +87,113 @@ export class ConsoleHandler extends BaseHandler { export abstract class WriterHandler extends BaseHandler { protected _writer!: Writer; - private _encoder = new TextEncoder(); + #encoder = new TextEncoder(); - log(msg: string): void { - this._writer.write(this._encoder.encode(msg + "\n")); - } + abstract log(msg: string): void; } interface FileHandlerOptions extends HandlerOptions { filename: string; + mode?: LogMode; } export class FileHandler extends WriterHandler { - private _file!: File; - private _filename: string; + protected _file!: File; + protected _filename: string; + protected _mode: LogMode; + #encoder = new TextEncoder(); constructor(levelName: string, options: FileHandlerOptions) { super(levelName, options); this._filename = options.filename; + // default to append mode, write only + this._mode = options.mode ? options.mode : "a"; } async setup(): Promise { - // open file in append mode - write only - this._file = await open(this._filename, "a"); + this._file = await open(this._filename, this._mode); this._writer = this._file; } + log(msg: string): void { + Deno.writeSync(this._file.rid, this.#encoder.encode(msg + "\n")); + } + async destroy(): Promise { await this._file.close(); } } + +interface RotatingFileHandlerOptions extends FileHandlerOptions { + maxBytes: number; + maxBackupCount: number; +} + +export class RotatingFileHandler extends FileHandler { + #maxBytes: number; + #maxBackupCount: number; + + constructor(levelName: string, options: RotatingFileHandlerOptions) { + super(levelName, options); + this.#maxBytes = options.maxBytes; + this.#maxBackupCount = options.maxBackupCount; + } + + async setup(): Promise { + if (this.#maxBytes < 1) { + throw new Error("maxBytes cannot be less than 1"); + } + if (this.#maxBackupCount < 1) { + throw new Error("maxBackupCount cannot be less than 1"); + } + await super.setup(); + + if (this._mode === "w") { + // Remove old backups too as it doesn't make sense to start with a clean + // log file, but old backups + for (let i = 1; i <= this.#maxBackupCount; i++) { + if (await exists(this._filename + "." + i)) { + await Deno.remove(this._filename + "." + i); + } + } + } else if (this._mode === "x") { + // 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); + throw new Deno.errors.AlreadyExists( + "Backup log file " + this._filename + "." + i + " already exists" + ); + } + } + } + } + + handle(logRecord: LogRecord): void { + if (this.level > logRecord.level) return; + + const msg = this.format(logRecord); + const currentFileSize = statSync(this._filename).size; + if (currentFileSize + msg.length > this.#maxBytes) { + this.rotateLogFiles(); + } + + return this.log(msg); + } + + rotateLogFiles(): void { + close(this._file.rid); + + for (let i = this.#maxBackupCount - 1; i >= 0; i--) { + const source = this._filename + (i === 0 ? "" : "." + i); + const dest = this._filename + "." + (i + 1); + + if (existsSync(source)) { + renameSync(source, dest); + } + } + + this._file = openSync(this._filename, this._mode); + this._writer = this._file; + } +} diff --git a/std/log/handlers_test.ts b/std/log/handlers_test.ts index 4feffdaf94..13b6de3bd9 100644 --- a/std/log/handlers_test.ts +++ b/std/log/handlers_test.ts @@ -1,8 +1,12 @@ // Copyright 2018-2020 the Deno authors. All rights reserved. MIT license. const { test } = Deno; -import { assertEquals } from "../testing/asserts.ts"; +import { assert, assertEquals, assertThrowsAsync } from "../testing/asserts.ts"; import { LogLevel, getLevelName, getLevelByName } from "./levels.ts"; -import { BaseHandler } from "./handlers.ts"; +import { BaseHandler, FileHandler, RotatingFileHandler } from "./handlers.ts"; +import { LogRecord } from "./logger.ts"; +import { existsSync } from "../fs/exists.ts"; + +const LOG_FILE = "./test_log.file"; class TestHandler extends BaseHandler { public messages: string[] = []; @@ -47,13 +51,9 @@ test(function simpleHandler(): void { for (const levelName in LogLevel) { const level = getLevelByName(levelName); - handler.handle({ - msg: `${levelName.toLowerCase()}-test`, - args: [], - datetime: new Date(), - level: level, - levelName: levelName, - }); + handler.handle( + new LogRecord(`${levelName.toLowerCase()}-test`, [], level) + ); } assertEquals(handler.level, testCase); @@ -67,13 +67,7 @@ test(function testFormatterAsString(): void { formatter: "test {levelName} {msg}", }); - handler.handle({ - msg: "Hello, world!", - args: [], - datetime: new Date(), - level: LogLevel.DEBUG, - levelName: "DEBUG", - }); + handler.handle(new LogRecord("Hello, world!", [], LogLevel.DEBUG)); assertEquals(handler.messages, ["test DEBUG Hello, world!"]); }); @@ -81,16 +75,229 @@ test(function testFormatterAsString(): void { test(function testFormatterAsFunction(): void { const handler = new TestHandler("DEBUG", { formatter: (logRecord): string => - `fn formmatter ${logRecord.levelName} ${logRecord.msg}`, + `fn formatter ${logRecord.levelName} ${logRecord.msg}`, }); - handler.handle({ - msg: "Hello, world!", - args: [], - datetime: new Date(), - level: LogLevel.ERROR, - levelName: "ERROR", - }); + handler.handle(new LogRecord("Hello, world!", [], LogLevel.ERROR)); - assertEquals(handler.messages, ["fn formmatter ERROR Hello, world!"]); + assertEquals(handler.messages, ["fn formatter ERROR Hello, world!"]); +}); + +test({ + name: "FileHandler with mode 'w' will wipe clean existing log file", + async fn() { + const fileHandler = new FileHandler("WARNING", { + filename: LOG_FILE, + mode: "w", + }); + + await fileHandler.setup(); + fileHandler.handle(new LogRecord("Hello World", [], LogLevel.WARNING)); + await fileHandler.destroy(); + const firstFileSize = (await Deno.stat(LOG_FILE)).size; + + await fileHandler.setup(); + fileHandler.handle(new LogRecord("Hello World", [], LogLevel.WARNING)); + await fileHandler.destroy(); + const secondFileSize = (await Deno.stat(LOG_FILE)).size; + + assertEquals(secondFileSize, firstFileSize); + Deno.removeSync(LOG_FILE); + }, +}); + +test({ + name: "FileHandler with mode 'x' will throw if log file already exists", + async fn() { + 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, + "ile exists" + ); + Deno.removeSync(LOG_FILE); + }, +}); + +test({ + name: + "RotatingFileHandler with mode 'w' will wipe clean existing log file and remove others", + async fn() { + Deno.writeFileSync(LOG_FILE, new TextEncoder().encode("hello world")); + Deno.writeFileSync( + LOG_FILE + ".1", + new TextEncoder().encode("hello world") + ); + Deno.writeFileSync( + LOG_FILE + ".2", + new TextEncoder().encode("hello world") + ); + Deno.writeFileSync( + LOG_FILE + ".3", + new TextEncoder().encode("hello world") + ); + + const fileHandler = new RotatingFileHandler("WARNING", { + filename: LOG_FILE, + maxBytes: 50, + maxBackupCount: 3, + mode: "w", + }); + await fileHandler.setup(); + await fileHandler.destroy(); + + assertEquals((await Deno.stat(LOG_FILE)).size, 0); + assert(!existsSync(LOG_FILE + ".1")); + assert(!existsSync(LOG_FILE + ".2")); + assert(!existsSync(LOG_FILE + ".3")); + + Deno.removeSync(LOG_FILE); + }, +}); + +test({ + name: + "RotatingFileHandler with mode 'x' will throw if any log file already exists", + async fn() { + 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" + ); + Deno.removeSync(LOG_FILE + ".3"); + Deno.removeSync(LOG_FILE); + }, +}); + +test({ + name: "RotatingFileHandler with first rollover", + async fn() { + const fileHandler = new RotatingFileHandler("WARNING", { + filename: LOG_FILE, + maxBytes: 25, + maxBackupCount: 3, + mode: "w", + }); + await fileHandler.setup(); + + fileHandler.handle(new LogRecord("AAA", [], LogLevel.ERROR)); // 'ERROR AAA\n' = 10 bytes + assertEquals((await Deno.stat(LOG_FILE)).size, 10); + fileHandler.handle(new LogRecord("AAA", [], LogLevel.ERROR)); + assertEquals((await Deno.stat(LOG_FILE)).size, 20); + fileHandler.handle(new LogRecord("AAA", [], LogLevel.ERROR)); + // 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 all backups rollover", + async fn() { + Deno.writeFileSync(LOG_FILE, new TextEncoder().encode("original log file")); + Deno.writeFileSync( + LOG_FILE + ".1", + new TextEncoder().encode("original log.1 file") + ); + Deno.writeFileSync( + LOG_FILE + ".2", + new TextEncoder().encode("original log.2 file") + ); + Deno.writeFileSync( + LOG_FILE + ".3", + new TextEncoder().encode("original log.3 file") + ); + + const fileHandler = new RotatingFileHandler("WARNING", { + filename: LOG_FILE, + maxBytes: 2, + maxBackupCount: 3, + mode: "a", + }); + await fileHandler.setup(); + fileHandler.handle(new LogRecord("AAA", [], LogLevel.ERROR)); // 'ERROR AAA\n' = 10 bytes + await fileHandler.destroy(); + + const decoder = new TextDecoder(); + assertEquals(decoder.decode(Deno.readFileSync(LOG_FILE)), "ERROR AAA\n"); + assertEquals( + decoder.decode(Deno.readFileSync(LOG_FILE + ".1")), + "original log file" + ); + assertEquals( + decoder.decode(Deno.readFileSync(LOG_FILE + ".2")), + "original log.1 file" + ); + assertEquals( + decoder.decode(Deno.readFileSync(LOG_FILE + ".3")), + "original log.2 file" + ); + assert(!existsSync(LOG_FILE + ".4")); + + Deno.removeSync(LOG_FILE); + Deno.removeSync(LOG_FILE + ".1"); + Deno.removeSync(LOG_FILE + ".2"); + Deno.removeSync(LOG_FILE + ".3"); + }, +}); + +test({ + name: "RotatingFileHandler maxBytes cannot be less than 1", + async fn() { + await assertThrowsAsync( + async () => { + const fileHandler = new RotatingFileHandler("WARNING", { + filename: LOG_FILE, + maxBytes: 0, + maxBackupCount: 3, + mode: "w", + }); + await fileHandler.setup(); + }, + Error, + "maxBytes cannot be less than 1" + ); + }, +}); + +test({ + name: "RotatingFileHandler maxBackupCount cannot be less than 1", + async fn() { + await assertThrowsAsync( + async () => { + const fileHandler = new RotatingFileHandler("WARNING", { + filename: LOG_FILE, + maxBytes: 50, + maxBackupCount: 0, + mode: "w", + }); + await fileHandler.setup(); + }, + Error, + "maxBackupCount cannot be less than 1" + ); + }, }); diff --git a/std/log/logger.ts b/std/log/logger.ts index 226b8dba61..9653d9008c 100644 --- a/std/log/logger.ts +++ b/std/log/logger.ts @@ -2,12 +2,26 @@ import { LogLevel, getLevelByName, getLevelName } from "./levels.ts"; import { BaseHandler } from "./handlers.ts"; -export interface LogRecord { - msg: string; - args: unknown[]; - datetime: Date; - level: number; - levelName: string; +export class LogRecord { + readonly msg: string; + #args: unknown[]; + #datetime: Date; + readonly level: number; + readonly levelName: string; + + constructor(msg: string, args: unknown[], level: number) { + this.msg = msg; + this.#args = [...args]; + this.level = level; + this.#datetime = new Date(); + this.levelName = getLevelName(level); + } + get args(): unknown[] { + return [...this.#args]; + } + get datetime(): Date { + return new Date(this.#datetime.getTime()); + } } export class Logger { @@ -26,16 +40,8 @@ export class Logger { _log(level: number, msg: string, ...args: unknown[]): void { if (this.level > level) return; - // TODO: it'd be a good idea to make it immutable, so - // no handler mangles it by mistake - // TODO: iterpolate msg with values - const record: LogRecord = { - msg: msg, - args: args, - datetime: new Date(), - level: level, - levelName: getLevelName(level), - }; + const record: LogRecord = new LogRecord(msg, args, level); + this.handlers.forEach((handler): void => { handler.handle(record); }); diff --git a/std/log/logger_test.ts b/std/log/logger_test.ts index 3e8898afaa..804591b4f9 100644 --- a/std/log/logger_test.ts +++ b/std/log/logger_test.ts @@ -10,7 +10,7 @@ class TestHandler extends BaseHandler { public records: LogRecord[] = []; handle(record: LogRecord): void { - this.records.push({ ...record }); + this.records.push(record); super.handle(record); } diff --git a/std/log/mod.ts b/std/log/mod.ts index 333e90fb9a..2f068f8ba7 100644 --- a/std/log/mod.ts +++ b/std/log/mod.ts @@ -5,6 +5,7 @@ import { ConsoleHandler, WriterHandler, FileHandler, + RotatingFileHandler, } from "./handlers.ts"; import { assert } from "../testing/asserts.ts"; @@ -47,6 +48,7 @@ export const handlers = { ConsoleHandler, WriterHandler, FileHandler, + RotatingFileHandler, }; export function getLogger(name?: string): Logger {