Logger implementation

[bartlomieju]

I'm opening this issue to start discussion on vision for logging module.

Coming from Python world and being familiar with its library, my intent for Deno logging was to emulate Python's approach.

Its mechanism is based on:

• loggers - object to call to log something obviously
• LogRecord - contains timestamps and metadata about message logged by logger
• handlers - also known as transports. One logger may utilize multiple `handlers. Eg. console handler that print output to console, file handler that streams logs to file on disk.
• filters - predicates that interact with LogRecords, allowing for very granular control. Both loggers and handlers can have filters
• formatters - a function that given LogRecord instance returns output string

Loggers are accessed using getLogger function, so wherever in code you do const logger = logging.getLogger('myLogger'); you get the same instance.

This page gives a nice overview how to use it in action.

One of more popular node's logging libraries winston takes not so different approach.

I'm really interested what community expects.

[ry]

1. I suggest we rename it to "log" - it's shorter.

2. I think the golang logger has reflected on python's and provides a good design to copy
   https://golang.org/pkg/log/

3. Currently Deno only has two built-in log-levels: debug and info. These can be in JS or Rust and are triggered by "-D"... Should the log module also be conditioned on "-D" ?

[bartlomieju]

1. Agreed
2. IMHO Go's logging module is low level compared to Python's. Do we want to provide simpler solution in standard library and leave it to user libraries to provide more battery-included solution?
3. I think so, default logging level should display only error and critical messages, while -D set default log level to debug.

[ry]

2. I kinda agree - although we need to provide some support for capturing logs and sending them elsewhere. Out of the box I'd like to be able to do

import * as log from "https://deno.land/std/log.ts";
log.debug("blah");
log.info("foo");

[bartlomieju]

@ry I totally agree. We can expose logging methods in exports, and those methods would call default logger.

Those two snippets would then be equivalent.

import * as log from "https://deno.land/std/log.ts";
log.debug("blah");
log.info("foo");

import * as log from "https://deno.land/std/log.ts";
const myLogger = log.getLogger();
myLogger.debug("blah");
myLogger.info("foo");

Regarding capturing and sending logs somewhere else, that's where Python's implementation shines.
We could do something like this:

import * as log from "https://deno.land/std/log.ts";
await log.config({
    handlers: {
        console: {
            level: 'debug',
            handler: new log.ConsoleHandler(),
        },
        file: {
            level: 'info',
            handler: new log.FileHandler(),
        },
    },
    loggers: {
        deno: {
            level: 'debug',
            handlers: ['console', 'file']
        }
    }
});

const logger = log.getLogger('deno');
logger.debug("blah"); // logged to console only
logger.info("foo");  // logged to both console and file

[kination]

@bartlomieju seems good!
Have one question...is log.config need await?

[bartlomieju]

Probably yes, I'm still trying to figure it out. But if you look for example at deno.open it's asynchronous, so making most of the handlers would be asynchronous operation. AFAIK you can't do asynchronous stuff in class constructor, so it might be rewritten to: await new FileHandler().setup({ filename })

[kination]

@bartlomieju please share to me how logger will be implemented when decided. I'll fix my PR by the guide if needed. Thanks for your work.

[bartlomieju]

@djKooks you can track progress in #51

[bartlomieju]

During chat conversation with @ry we concluded that logging methods should take only one argument msg and leave it to user to format message properly, eg.

import * as deno from 'deno';
import * as log from 'https://deno.land/x/std/logging/index.ts';
const someNum = 100;
const someObj = { a: 1, b: 2 };
// instead of interpolation ...
log.info("Number: %n, object: %o", someNum, someObj);
// just use template strings
log.info(`Number: ${someNum}, object: ${deno.inspect(someObj)}`)

This minimizes the API that has to be implemented.

As for output format of each message, Glog's style was proposed (also here). Note: we're not sure why leading bracket [ is missing in glog's format.

Proposed format:

[Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg

where:

• L - level of message
• mmdd - month and day
• hh:mm:ss.uuuuuu - timestamp
• threadid - PID of thread/process
• file:line - filename and line from where message originated. Not sure we can get that info currently.

Example line would look like this:

[D0301 10:04:23:43111 3451 main.ts:30] Some logged message

To be honest I'm not a big fan of this format, I'd prefer to output ISO date like this:

[D 2018-01-03 10:04:23:43111 pid:3451 main.ts:30] Some logged message

[hayd]

Would this be configurable?

[ry]

[D0301 10:04:23:43111 3451 main.ts:30] Some logged message

Have you thought about how to extract "main.ts:30" ?

Note: we're not sure why leading bracket [ is missing in glog's format.

If we're going to use glogs format, let's copy it exactly, including the unmatched bracket. It's not a mistake. I just don't know the reason for it.

To be honest I'm not a big fan of this format

Your proposed format is longer...

Would this be configurable?

I'd rather we agree on one format...

[bartlomieju]

Have you thought about how to extract "main.ts:30" ?

My initial idea was to leverage Error.stack but I'm concerned with performance, throwing error at each logged message can't be a good idea.

To be honest I'm not a big fan of this format

Your proposed format is longer...

It is, but glog's format is hard to grep when you see it for first time, especially conjunction of log level and date. But I'm not sticking to it no matter what.

Would this be configurable?

I'd rather we agree on one format...

That's fine for me, but it will bring a need for another logging libraries that allow to configure that.

[ry]

My initial idea was to leverage Error.stack but I'm concerned with performance, throwing error at each logged message can't be a good idea.

Hm.. It's possible we could provide __LINE__ as a preprocessed symbol in deno. For the filename we could use import.meta once denoland/deno#975 lands.

[bartlomieju]

@ry one more comment on configurable format - tests would be much simpler if format could be manipulated, eg. date could be skipped. Otherwise we'd need some kind of wildcard matching?

[ry]

@bartlomieju true good point.

[bartlomieju]

After some consideration I think we might want to change LogRecord and signature of logging methods from:

export interface LogRecord {
  msg: string;
  args: any[];
  datetime: Date;
  level: number;
  levelName: string;
}

debug(msg: string, ...args: any[]) {
    return this._log(LogLevel.DEBUG, msg, ...args);
}

to:

type LogMetadata = {[key: string]: any};

export interface LogRecord {
  msg: string;
  metadata?: LogMetadata;
  datetime: Date;
  level: number;
  levelName: string;
}

debug(msg: string, metadata?: LogMetadata) {
    return this._log(LogLevel.DEBUG, msg, metadata);
}

this object would be placed in LogRecord and be later utilized in custom formatter. Simple but powerful IMHO.

[ry]

@bartlomieju That seems like more to type? Or maybe I misunderstand. Can you give some examples of invocation?

[bartlomieju]

Yeah after all it seems so. My initial idea was that args would be interpolated in msg (msg % args), but we already established that we don't want that.

We could keep LogRecord.args and allow to use that instead of metadata

[bartlomieju]

I reckon log implementation is good enough now we can close this.