Overview

Logger utility to log messages.

Usage

Once the logger is added to package.json and installed, it can be used in following way

var logger = require("oe-logger");
var log = logger("testlog");

log.debug(context, arg1, arg2);
log.info(context, arg1, arg2);
log.warn(context, arg1, arg2);
log.error(context, arg1, arg2);
log.fatal(context, arg1, arg2);

The log functions accepts atleast two parameters, * first parameter is context which would be the callContext for the request * second parameter onward can be String or Object as they will be printed as a concatenated string.

The logger requires a configuration to be passed as environment variable LOGGER_CONFIG. In case, no value is passed, then it uses default config, which is

{"logStreams": [{"type": "pretty"}],"levels": {"default": "info"}, "enableContextLogging": false}

Log Streams

Support for three log streams is provided, which are * Standard Output: Prints log as JSON on the console * Pretty Standard Output: Prints log in a pretty format on the console * UDP stream: Streams log to a udp stream using gelf

Following are examples for configuring them for different log streams (standard output, pretty output, udp stream) respectively,

export LOGGER_CONFIG={"logStreams":[{"type":"out"}],"levels":{"default":"debug"},"enableContextLogging":1}

export LOGGER_CONFIG={"logStreams":[{"type":"pretty"}],"levels":{"default":"debug"},"enableContextLogging":1}

export LOGGER_CONFIG={"logStreams":[{"type":"udp", "host":"127.0.0.1", "port":"1234"}],"levels":{"default":"debug"},"enableContextLogging":1}

export LOGGER_CONFIG={"logStreams":[{"type":"file","path":"./a.log","level":"debug"}],"levels":{"default":"debug"},"enableContextLogging":1}

export LOGGER_CONFIG={"logStreams":[{"type":"rotating-file","path":"./a.log","level":"debug", "period": "1d", "count": 3}],"levels":{"default":"debug"},"enableContextLogging":1}
Note: for rotating-file, following are optional, 
period - The period at which to rotate. This is a string of the format "$number$scope" where "$scope" is one of "ms" (milliseconds -- only useful for testing), "h" (hours), "d" (days), "w" (weeks), "m" (months), "y" (years). Or one of the following names can be used "hourly" (means 1h), "daily" (1d), "weekly" (1w), "monthly" (1m), "yearly" (1y). Rotation is done at the start of the scope: top of the hour (h), midnight (d), start of Sunday (w), start of the 1st of the month (m), start of Jan 1st (y).
count - The number of rotated files to keep.

export LOGGER_CONFIG='{"name":"oe-cloud-app","logStreams":[{"type":"file","path":"./a.log"}],"levels":{"default":"info","module-a":"trace","module-b":"error"}}'
Note: module-a and module-b are name given to initialize the logged in respective modules, e.g. var log = require("oe-logger")("module-a")

Following are error log statement log.error({}, "sample log"); the output for out and pretty streams are as follows respectively:

{"name":"oe-logger","hostname":"HOSTNAME","pid":9940,"__name__":"test","level":50,"msg":"sample log","time":"2016-01-01T11:28:50.643Z","v":0}

[2016-01-01T11:28:29.126Z] ERROR: oe-logger on HOSTNAME: sample log (test)

Log Arguments

The first argument for the log statements can be call context, which allow to log modelName, remoteUser, tenantId and requestId related to the request being sent. These values are being placed in options/context of the request which can be passed as first argument to log them for easy filtering of requests.

Following is example to log a request details from the req-logging-filter, which passes the callContext as first argument for BaseUsers login API for admin user

log.debug(req.callContext, "Body: ", req.body);
[2017-07-11T06:20:55.726Z] DEBUG: oe-logger on HOSTNAME: Body:  {"username":"admin","password":"admin"} (req-logging-filter, BaseUsers, system, default, 18c036a0-6601-11e7-9cc9-fbb7d2f1cd6b)

Logs in Local Time

Set the tzoffset to ’local’ in logger configuration to get the logs in local time. tzoffset can also be set to local using LOGGER_TZOFFSET env variable

export LOGGER_CONFIG={"logStreams":[{"type":"pretty"}],"levels":{"default":"debug"},"enableContextLogging":1, "tzoffset": "local"}
export LOGGER_TZOFFSET = 'local'

The log will be like this in local time showing timezone offset in hours

[2020-12-22T11:10:39.736 +5:30] ERROR: oe-logger on HOSTNAME: { cat: 'meow', dog: 'woof' } (logger-test)

In order to get the logs based on user’s desired (irrespective of local time) time, tzoffset should be a offset time in ‘hh:mm’ format in any of the below formats:

  • ‘+05:30’ or ‘-05:30’
  • ‘+5:30’ or ‘-5:30’
  • ‘5:30’
  • 5 or -5 (when the offset is 5 hours, we can directly specify the hours in number)
export LOGGER_CONFIG={"logStreams":[{"type":"pretty"}],"levels":{"default":"debug"},"enableContextLogging":1, "tzoffset": "+05:30"}
export LOGGER_TZOFFSET = '+05:30'

Note:

  • when tzoffset is set to local, oe-logger will log the logs in local time (system time)
  • when tzoffset is set to ‘hh:mm’ offset format, logs will be in any desired time based on tzoffset given by the user

Let the user’s timezone be IST (GMT +05:30)

  • when tzoffset is set to local, the time will be in local time [2020-12-22T11:10:39.736 +5:30]
  • when tzoffset is set to ‘+13:00’, the time will be [2020-12-22T18:40:39.736 +13:00]

Sensitive Data Masking

Care should be taken not to log any sensitive data like password, access-tokens in the logs. Any explicit logging can be avoided by proper code reviews. However, sometimes when complete javascript object is being logged, it may contain certain sensitive information. oe-logger allows providing maskKeys as a setting in LOGGER_CONFIG. This should be an array containing fields that need to be masked whrever it occurs in a logged json object.

export LOGGER_CONFIG={"logStreams":[{"type":"pretty"}],"levels":{"default":"debug"},"enableContextLogging":1, "maskKeys": ["password", "secret"]}

Above example will look for password and secret fields in the object recursively and mask with asteriscs.

Consider following payload,

let input = {
  userDetails: {
    id: 5,
    name: 'John',
    password: "t0ps3cr3t"
  },
  secret: "s3cr3t-k3y",
  xyz: null,
  datasources: [{value: 99, password: "h1d3!t"}, "string-data", {value: 8, myPassword: "w0ntH1d3"}]
}

And a log statement like

log.warn(context, 'Masking Test %j', input);

This results in following log output.

[2022-07-29T02:57:39.867Z]  WARN: oe-logger on runner-db2qTJ5q-project-3463-concurrent-0: Masking Test {"userDetails":{"id":5,"name":"John","password":"********"},"secret":"********","xyz":null,"datasources":[{"value":99,"password":"********"},"string-data",{"value":8,"myPassword":"w0ntH1d3"}]} (logger-test, 10, uiahyd8239ye89dh278g39d29)

The values for password and secret fields are masked.

The feature does not protect against following kind of log statements.

 log.warn("The supplied secret %s is invalid", input.secret);