Improve logging module (#51)

azure-pipelines.yml

@@ -26,4 +26,4 @@ jobs:
 #  steps:
 #  - powershell: iex (iwr https://deno.land/x/install/install.ps1)
 #  - script: echo '##vso[task.prependpath]C:\Users\VssAdministrator\.deno\bin\'
-#  - script: 'C:\Users\VssAdministrator\.deno\bin\deno.exe test.ts --allow-run --allow-net'
+#  - script: 'C:\Users\VssAdministrator\.deno\bin\deno.exe test.ts --allow-run --allow-net --allow-write'

logging/README.md

@@ -1,15 +1,38 @@
-# Logging module for Deno
+# Basic usage
 
-Very much work in progress. Contributions welcome.
+```ts
+import * as log from "https://deno.land/x/std/logging/index.ts";
 
-This library is heavily inspired by Python's
-[logging](https://docs.python.org/3/library/logging.html#logging.Logger.log)
-module, altough it's not planned to be a direct port. Having separate loggers,
-handlers, formatters and filters gives developer very granular control over
-logging which is most desirable for server side software.
+// simple console logger
+log.debug("Hello world");
+log.info("Hello world");
+log.warning("Hello world");
+log.error("Hello world");
+log.critical("500 Internal server error");
 
-Todo:
+// configure as needed
+await log.setup({
+    handlers: {
+        console: new log.handlers.ConsoleHandler("DEBUG"),
+        file: new log.handlers.FileHandler("WARNING", "./log.txt"),
+    },
 
-- [ ] implement formatters
-- [ ] implement `FileHandler`
-- [ ] tests
+    loggers: {
+        default: {
+            level: "DEBUG",
+            handlers: ["console", "file"],
+        }
+    }
+});
+
+// get configured logger
+const logger = log.getLogger("default");
+logger.debug("fizz") // <- logs to `console`, because `file` handler requires 'WARNING' level
+logger.warning("buzz") // <- logs to both `console` and `file` handlers
+
+// if you try to use a logger that hasn't been configured
+// you're good to go, it gets created automatically with level set to 0
+// so no message is logged
+const unknownLogger = log.getLogger("mystery");
+unknownLogger.info("foobar") // no-op
+```

logging/handler.ts

@@ -1,18 +0,0 @@
-import { getLevelByName } from "./levels.ts";
-
-export class BaseHandler {
-  level: number;
-  levelName: string;
-
-  constructor(levelName) {
-    this.level = getLevelByName(levelName);
-    this.levelName = levelName;
-  }
-
-  handle(level, ...args) {
-    if (this.level > level) return;
-    return this._log(level, ...args);
-  }
-
-  _log(level, ...args) {}
-}

logging/handlers.ts

@@ -0,0 +1,65 @@
+import { open, File, Writer } from "deno";
+import { getLevelByName } from "./levels.ts";
+import { LogRecord } from "./logger.ts";
+
+export class BaseHandler {
+  level: number;
+  levelName: string;
+
+  constructor(levelName: string) {
+    this.level = getLevelByName(levelName);
+    this.levelName = levelName;
+  }
+
+  handle(logRecord: LogRecord) {
+    if (this.level > logRecord.level) return;
+
+    // TODO: implement formatter
+    const msg = `${logRecord.levelName} ${logRecord.msg}`;
+
+    return this.log(msg);
+  }
+
+  log(msg: string) { }
+  async setup() { }
+  async destroy() { }
+}
+
+
+export class ConsoleHandler extends BaseHandler {
+  log(msg: string) {
+    console.log(msg);
+  }
+}
+
+
+export abstract class WriterHandler extends BaseHandler {
+  protected _writer: Writer;
+
+  log(msg: string) {
+    const encoder = new TextEncoder();
+    // promise is intentionally not awaited
+    this._writer.write(encoder.encode(msg + "\n"));
+  }
+}
+
+
+export class FileHandler extends WriterHandler {
+  private _file: File;
+  private _filename: string;
+
+  constructor(levelName: string, filename: string) {
+    super(levelName);
+    this._filename = filename;
+  }
+
+  async setup() {
+    // open file in append mode - write only
+    this._file = await open(this._filename, 'a');
+    this._writer = this._file;
+  }
+
+  async destroy() {
+    await this._file.close();
+  }
+}

logging/handlers/console.ts

@@ -1,26 +0,0 @@
-import { BaseHandler } from "../handler.ts";
-import { LogLevel } from "../levels.ts";
-
-export class ConsoleHandler extends BaseHandler {
-  _log(level, ...args) {
-    switch (level) {
-      case LogLevel.DEBUG:
-        console.log(...args);
-        return;
-      case LogLevel.INFO:
-        console.info(...args);
-        return;
-      case LogLevel.WARNING:
-        console.warn(...args);
-        return;
-      case LogLevel.ERROR:
-        console.error(...args);
-        return;
-      case LogLevel.CRITICAL:
-        console.error(...args);
-        return;
-      default:
-        return;
-    }
-  }
-}

logging/index.ts

@@ -1,21 +1,14 @@
 import { Logger } from "./logger.ts";
-import { BaseHandler } from "./handler.ts";
-import { ConsoleHandler } from "./handlers/console.ts";
-
-export interface HandlerConfig {
-  // TODO: replace with type describing class derived from BaseHandler
-  class: typeof BaseHandler;
-  level?: string;
-}
+import { BaseHandler, ConsoleHandler, WriterHandler, FileHandler } from "./handlers.ts";
 
 export class LoggerConfig {
   level?: string;
   handlers?: string[];
 }
 
-export interface LoggingConfig {
+export interface LogConfig {
   handlers?: {
-    [name: string]: HandlerConfig;
+    [name: string]: BaseHandler;
   };
   loggers?: {
     [name: string]: LoggerConfig;
@@ -24,78 +17,95 @@ export interface LoggingConfig {
 
 const DEFAULT_LEVEL = "INFO";
 const DEFAULT_NAME = "";
-const DEFAULT_CONFIG: LoggingConfig = {
+const DEFAULT_CONFIG: LogConfig = {
   handlers: {
-    [DEFAULT_NAME]: {
-      level: DEFAULT_LEVEL,
-      class: ConsoleHandler
-    }
+    
   },
 
   loggers: {
-    [DEFAULT_NAME]: {
-      level: DEFAULT_LEVEL,
-      handlers: [DEFAULT_NAME]
+    "": {
+      level: "INFO",
+      handlers: [""],
     }
   }
 };
 
+const defaultHandler = new ConsoleHandler("INFO");
+const defaultLogger = new Logger("INFO", [defaultHandler]);
+
 const state = {
+  defaultHandler,
+  defaultLogger,
+  handlers: new Map(),
   loggers: new Map(),
-  config: DEFAULT_CONFIG
+  config: DEFAULT_CONFIG,
 };
 
-function createNewHandler(name: string) {
-  let handlerConfig = state.config.handlers[name];
-
-  if (!handlerConfig) {
-    handlerConfig = state.config.handlers[DEFAULT_NAME];
-  }
-
-  const constructor = handlerConfig.class;
-  console.log(constructor);
-  const handler = new constructor(handlerConfig.level);
-  return handler;
-}
-
-function createNewLogger(name: string) {
-  let loggerConfig = state.config.loggers[name];
-
-  if (!loggerConfig) {
-    loggerConfig = state.config.loggers[DEFAULT_NAME];
-  }
-
-  const handlers = (loggerConfig.handlers || []).map(createNewHandler);
-  const levelName = loggerConfig.level || DEFAULT_LEVEL;
-  return new Logger(levelName, handlers);
-}
-
 export const handlers = {
-  BaseHandler: BaseHandler,
-  ConsoleHandler: ConsoleHandler
+  BaseHandler,
+  ConsoleHandler,
+  WriterHandler,
+  FileHandler,
 };
 
+export const debug = (msg: string, ...args: any[]) => defaultLogger.debug(msg, ...args);
+export const info = (msg: string, ...args: any[]) => defaultLogger.info(msg, ...args);
+export const warning = (msg: string, ...args: any[]) => defaultLogger.warning(msg, ...args);
+export const error = (msg: string, ...args: any[]) => defaultLogger.error(msg, ...args);
+export const critical = (msg: string, ...args: any[]) => defaultLogger.critical(msg, ...args);
+
 export function getLogger(name?: string) {
   if (!name) {
-    name = DEFAULT_NAME;
+    return defaultLogger;
   }
 
   if (!state.loggers.has(name)) {
-    return createNewLogger(name);
+    const logger = new Logger("NOTSET", []);
+    state.loggers.set(name, logger);
+    return logger;
   }
 
   return state.loggers.get(name);
 }
 
-export function setup(config: LoggingConfig) {
-  state.config = {
-    handlers: {
-      ...DEFAULT_CONFIG.handlers,
-      ...config.handlers!
-    },
-    loggers: {
-      ...DEFAULT_CONFIG.loggers,
-      ...config.loggers!
-    }
-  };
+export async function setup(config: LogConfig) {
+  state.config = config;
+
+  // tear down existing handlers
+  state.handlers.forEach(handler => {
+    handler.destroy();
+  });
+  state.handlers.clear();
+
+  // setup handlers
+  const handlers = state.config.handlers || {};
+
+  for (const handlerName in handlers) {
+    const handler = handlers[handlerName];
+    await handler.setup();
+    state.handlers.set(handlerName, handler);
+  }
+
+  // remove existing loggers
+  state.loggers.clear();
+
+  // setup loggers
+  const loggers = state.config.loggers || {};
+  for (const loggerName in loggers) {
+    const loggerConfig = loggers[loggerName];
+    const handlerNames = loggerConfig.handlers || [];
+    const handlers = [];
+
+    handlerNames.forEach(handlerName => {
+      if (state.handlers.has(handlerName)) {
+        handlers.push(state.handlers.get(handlerName));
+      }
+    });
+
+    const levelName = loggerConfig.level || DEFAULT_LEVEL;
+    const logger = new Logger(levelName, handlers);
+    state.loggers.set(loggerName, logger);
+  }
 }
+
+setup(DEFAULT_CONFIG);

logging/levels.ts

@@ -1,4 +1,5 @@
 export const LogLevel = {
+  NOTSET: 0,
   DEBUG: 10,
   INFO: 20,
   WARNING: 30,
@@ -7,14 +8,16 @@ export const LogLevel = {
 };
 
 const byName = {
+  NOTSET: LogLevel.NOTSET,
   DEBUG: LogLevel.DEBUG,
   INFO: LogLevel.INFO,
   WARNING: LogLevel.WARNING,
   ERROR: LogLevel.ERROR,
-  CRITICAL: LogLevel.DEBUG
+  CRITICAL: LogLevel.CRITICAL
 };
 
 const byLevel = {
+  [LogLevel.NOTSET]: "NOTSET",
   [LogLevel.DEBUG]: "DEBUG",
   [LogLevel.INFO]: "INFO",
   [LogLevel.WARNING]: "WARNING",
@@ -22,10 +25,10 @@ const byLevel = {
   [LogLevel.CRITICAL]: "CRITICAL"
 };
 
-export function getLevelByName(name) {
+export function getLevelByName(name: string): number {
   return byName[name];
 }
 
-export function getLevelName(level) {
+export function getLevelName(level: number): string {
   return byLevel[level];
 }

logging/logger.ts

@@ -1,44 +1,62 @@
 import { LogLevel, getLevelByName, getLevelName } from "./levels.ts";
+import { BaseHandler } from "./handlers.ts";
+
+export interface LogRecord {
+  msg: string;
+  args: any[];
+  datetime: Date;
+  level: number;
+  levelName: string;
+};
 
 export class Logger {
   level: number;
   levelName: string;
   handlers: any[];
 
-  constructor(levelName, handlers) {
+  constructor(levelName: string, handlers?: BaseHandler[]) {
     this.level = getLevelByName(levelName);
     this.levelName = levelName;
-    this.handlers = handlers;
+    
+    this.handlers = handlers || [];
   }
 
-  _log(level, ...args) {
+  _log(level: number, msg: string, ...args: any[]) {
+    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),
+    }
+
     this.handlers.forEach(handler => {
-      handler.handle(level, ...args);
+      handler.handle(record);
     });
   }
 
-  log(level, ...args) {
-    if (this.level > level) return;
-    return this._log(level, ...args);
+  debug(msg: string, ...args: any[]) {
+    return this._log(LogLevel.DEBUG, msg, ...args);
   }
 
-  debug(...args) {
-    return this.log(LogLevel.DEBUG, ...args);
+  info(msg: string, ...args: any[]) {
+    return this._log(LogLevel.INFO, msg, ...args);
   }
 
-  info(...args) {
-    return this.log(LogLevel.INFO, ...args);
+  warning(msg: string, ...args: any[]) {
+    return this._log(LogLevel.WARNING, msg, ...args);
   }
 
-  warning(...args) {
-    return this.log(LogLevel.WARNING, ...args);
+  error(msg: string, ...args: any[]) {
+    return this._log(LogLevel.ERROR, msg, ...args);
   }
 
-  error(...args) {
-    return this.log(LogLevel.ERROR, ...args);
-  }
-
-  critical(...args) {
-    return this.log(LogLevel.CRITICAL, ...args);
+  critical(msg: string, ...args: any[]) {
+    return this._log(LogLevel.CRITICAL, msg, ...args);
   }
 }

logging/test.ts

@@ -1,53 +1,84 @@
+import { remove, open, readAll } from "deno";
 import { assertEqual, test } from "https://deno.land/x/testing/testing.ts";
 
-import * as logging from "index.ts";
+import * as log from "index.ts";
+import { FileHandler } from "./handlers.ts";
 
 // TODO: establish something more sophisticated
-
 let testOutput = "";
 
-class TestHandler extends logging.handlers.BaseHandler {
-  _log(level, ...args) {
-    testOutput += `${level} ${args[0]}\n`;
+class TestHandler extends log.handlers.BaseHandler {
+  constructor(levelName: string) {
+    super(levelName);
+  }
+
+  log(msg: string) {
+    testOutput += `${msg}\n`;
   }
 }
 
-logging.setup({
-  handlers: {
-    debug: {
-      level: "DEBUG",
-      class: TestHandler
-    },
+test(function testDefaultlogMethods() {
+  log.debug("Foobar");
+  log.info("Foobar");
+  log.warning("Foobar");
+  log.error("Foobar");
+  log.critical("Foobar");
 
-    info: {
-      level: "INFO",
-      class: TestHandler
-    }
-  },
-
-  loggers: {
-    default: {
-      level: "DEBUG",
-      handlers: ["debug"]
-    },
-
-    info: {
-      level: "INFO",
-      handlers: ["info"]
-    }
-  }
+  const logger = log.getLogger('');
+  console.log(logger);
 });
 
-const logger = logging.getLogger("default");
-const unknownLogger = logging.getLogger("info");
+test(async function basicTest() {
+  const testFile = './log.txt';
 
-test(function basicTest() {
-  logger.debug("I should be printed.");
-  unknownLogger.debug("I should not be printed.");
-  unknownLogger.info("And I should be printed as well.");
+  await log.setup({
+    handlers: {
+      debug: new TestHandler("DEBUG"),
+      info: new TestHandler("INFO"),
+      file: new FileHandler("DEBUG", testFile),
+    },
 
+    loggers: {
+      foo: {
+        level: "DEBUG",
+        handlers: ["debug", "file"]
+      },
+
+      bar: {
+        level: "INFO",
+        handlers: ["info"]
+      }
+    }
+  });
+
+  const fooLogger = log.getLogger("foo");
+  const barLogger = log.getLogger("bar");
+  const bazzLogger = log.getLogger("bazz");
+  
+
+  fooLogger.debug("I should be logged.");
+  fooLogger.debug("I should be logged.");
+  barLogger.debug("I should not be logged.");
+  barLogger.info("And I should be logged as well.");
+  bazzLogger.critical("I shouldn't be logged neither.")
+  
   const expectedOutput =
-    "10 I should be printed.\n20 And I should be printed as well.\n";
+    "DEBUG I should be logged.\n" +
+    "DEBUG I should be logged.\n" +
+    "INFO And I should be logged as well.\n";
 
   assertEqual(testOutput, expectedOutput);
+
+  // same check for file handler
+  const f = await open(testFile);
+  const bytes = await readAll(f);
+  const fileOutput = new TextDecoder().decode(bytes);
+  await f.close();
+  await remove(testFile);
+
+  const fileExpectedOutput = 
+    "DEBUG I should be logged.\n" +
+    "DEBUG I should be logged.\n";
+
+  assertEqual(fileOutput, fileExpectedOutput);
 });