feat(std/log): improvements and new log handler (#4674)

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

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<void> {
-    // 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<void> {
     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<void> {
+    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;
+  }
+}

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"
+    );
+  },
 });

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);
     });

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);
   }
 

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 {