tobiipro / minlog Goto Github PK

Is it really "Min" after that?

Both Andreas F and I have encountered this problem. Although not a big problem it can be quite confusing the first time seeing it.

So far, we have not seen any clear pattern of what is causing this.

We had a hypothesis that it something to do with deploying a lambda from the terminal (vs deployed from Travis) but when tested it worked also for this case.

In the minimal setup like

let {
  MinLog,
  logToConsole
} = require('./src/index');

let logger = new MinLog({
  listeners: [
    logToConsole({
      level: 'INFO'
    })
  ],
  serializers: []
});
logger.info('test');

crashes with

(node:75745) UnhandledPromiseRejectionWarning: TypeError: (0 , _moment.default)(
...).utcOffset(...).toISOString is not a function
    at Object.toISOString [as serialize] (/Users/isao/code/github/TobiiPro/minlo
g/src/listeners/log-to-console.js:56:73)
    at /Users/isao/code/github/TobiiPro/minlog/src/listeners/log-to-console.js:2
02:9
    at MinLog.listener [as log] (/Users/isao/code/github/TobiiPro/minlog/src/min
log.js:142:13)
    at apply (/Users/isao/code/github/TobiiPro/minlog/node_modules/lodash/lodash
.js:478:17)
    at MinLog.wrapper [as info] (/Users/isao/code/github/TobiiPro/minlog/node_mo
dules/lodash/lodash.js:5323:16)
    at Object.info (/Users/isao/code/github/TobiiPro/minlog/test.js:16:8)
    at Module._compile (internal/modules/cjs/loader.js:721:30)
    at Module._compile (/Users/isao/code/github/TobiiPro/minlog/node_modules/pir
ates/lib/index.js:99:24)
    at Module._extensions..js (internal/modules/cjs/loader.js:732:10)
    at Object.newLoader [as .js] (/Users/isao/code/github/TobiiPro/minlog/node_m
odules/pirates/lib/index.js:104:7)

• indentation
• references, see [Object]

2019-02-18T15:30:30.204Z        9e0091ed-1e7c-4ad4-a8ea-8681870c616a    2019-02-18T15:30:30.182Z TRACE in the ? context:

Logger started. TRACE
{ _arg0: 'Logger started. TRACE' }
{ _arg1:
{ e:
{ resource: '/sql',
path: '/sql',
httpMethod: 'POST',
headers: [Object],

aws lambda monkey-patches console functions to add timestamps themselves... so log entries show up as

2019-02-18T15:30:30.203Z 9e0091ed-1e7c-4ad4-a8ea-8681870c616a 2019-02-18T15:30:30.182Z TRACE in the ? context:

Repro example:

let {
  MinLog,
  logToConsole,
  serializeTime
} = require('./src/index');

let logger = new MinLog({
  listeners: [
    logToConsole({
      level: 'INFO'
    })
  ],
  serializers: [
    serializeTime
  ]
});

let A = class {
  constructor() {
    this.test = 'test';
  }
};

logger.info('test', new A());

Receiving:

2019-03-01T15:54:36.047Z  INFO
test

Expected: probably, MinLog should call toString of the object.

out of curiousity I just ran the basic benchmarking available at https://github.com/pinojs/pino npm run bench-basic

BASIC benchmark averages
Bunyan average: 680.751ms
Winston average: 496.127ms
Bole average: 375.836ms
Debug average: 328.526ms
LogLevel average: 328.303ms
MinLog average: 474.515ms
Pino average: 240.441ms
PinoExtreme average: 103.965ms
PinoNodeStream average: 219.996ms

I identified some red flags, that when/if removed takes minlog to:

BASIC benchmark averages
Bunyan average: 707.045ms
Winston average: 1885.363ms
Bole average: 627.995ms
Debug average: 416.026ms
LogLevel average: 452.593ms
MinLog average: 196.916ms
Pino average: 287.970ms
PinoExtreme average: 131.185ms
PinoNodeStream average: 283.553ms

red flags:

• new Date() --- could consider Date.now()
• getCallerInfo --- could be optional
• rawEntry --- cloneDeep is expensive, could be optional

Minimal reproduce code

let {
  MinLog,
  logToConsole,
  serializeTime
} = require('./src/index');

let logger = new MinLog({
  listeners: [
    logToConsole({
      level: 'INFO'
    })
  ],
  serializers: [
    serializeTime
  ]
});

logger.info('test', {
  obj: 'a'
}, {
  hej: 'b'
}, {
  yo: 'c'
});

Receiving in console:

2019-03-01T14:38:24.860Z  INFO
test
{
  "hej": "b"
}
{
  "obj": "a"
}
{
  "yo": "c"
}

Expected: objects to be in order like a, b, c

Logging a return value from a call to axios in an AWS lambda function using minlog messed up the CloudWatch console so that log entries was not shown and the ones that were shown were incomplete and difficult to read. Probably because the stringified version of the object got very long.

Logging it with console.log worked fine and did not have that effect.

When calling minlog e.g. like this:

  logger.log('foo');

there will be an error thrown stating:
Error: Unknown level name . Known: time,fatal,verbose,silly,emergency,alert,critical,error,warning,notice,informational,debug,warn,info,trace.

The log level used is not specified in the error message (which seems to be the intention).

It seems like all lines logged by minlog contains the string "in apply() ".

Afaics those characters don't add any value to the log output.

https://user-images.githubusercontent.com/7059915/66752558-02231400-ee92-11e9-9609-5b8ef48f2713.png

see lodash-firecloud setup

I think that iframeId is atex-web-ext-specific thing. Suggesting to replace it with some kind of generic context.

when logging in the browser, you log references, which in turns means that anything that is folded may not accurate when you unfold. see https://stackoverflow.com/questions/5223513/why-doesnt-console-log-take-a-snapshot-of-the-passed-variables

this is only possible in the browser, and the benefit of logging references versus snapshots are closer to corner cases, as in it happens seldom, and when you do it you do not expect that log entry to ever change

a suggestion would be that minlog could be configurable to log snapshots instead, and MinLog::ref(variable) would be a function that returns a MinLog.Ref instance, that when logged would make MinLog to log the variable instead of the snapshot.

minlog.info(window); // log a snapshot of window, probably not performant at all
minlog.info(minlog.ref(window)); // log a reference of window, just like console.log does

relevant code in minlog/src/listeners/log-to-console.js, line 219 extraArgs.push(value); could be changed to say extraArgs.push(value instanceOf MinLog.Ref ? value : JSON.parse(fastSafeStringify(value)));

basically if a serializer returns undefined, shortcircuit the logging (don't call the rest of the serializers, and don't call the listeners)