# ssi-logger

Simplified logging for node.js modules.

## Features

* any code running in the `node` instance, including external modules, can append log messages.
* the external modules don't need any configuration knowledge to send messages to the log.
* there is no need to pass around a `syslog` object to every function that needs to log something.
* log messages can be directed anywhere, not just to syslog and console.
* log messages can go to 0, 1, or many destinations (/dev/null, syslog, file, rabbitmq, e-mail, XMPP, etc).
* a log destination can be turned on or off at runtime.
* logged objects are automatically formatted into key=value strings (great for sending messages to [splunk](http://www.splunk.com/)).
* certain fields can be censored to avoid accidentally logging sensitive information.
* formatted log messages are returned by SSi Logger to the caller.
* it accepts multiple arguments and printf-style formats just like `console.log`.
* defaults can be supplied that are included in every message.
* your choice of API: `log(level, message, ...)` or `log.level(message, ...)`

## Theory of Operation

The module provides a `log(level, message, ...)` function which accepts the log level (`INFO`, `NOTICE`, `DEBUG`, etc)
and a log message. The message argument(s) work just like [console.log()](https://nodejs.org/api/console.html#console_console_log_data),
supporting a variable number of arguments plus formatting.

When invoked, the logger will format the log message using [logformat](https://github.com/tcort/logformat)
(for example, a JSON object like `[ { name: 'Tom' }, { name: 'Phil' } ]` becomes `0.name=Tom 1.name=Phil`).
The log level and message are emitted as a `log` event though the `process` event emitter. The main
application will provide an event listener to forward the log message to syslog or any other destination
(RabbitMQ, log file, database, etc). Finally, the logging function returns the formatted log message
which can be displayed/returned to the user if desired.

## Installation

    npm install --save ssi-logger

## Examples

Basic Usage:

    const options = {
        logger: {
            transports: {
                syslog: {facility: "LOG_LOCAL5", level: "DEBUG"},
                console: {timestamp: true},
            }
        }
    };
    
    log.open(options.logger.transports);
    
    log.info('Ready to rock!');


Multiple message arguments:

    log('INFO', 'Hello,', 'World!');
    // emits ---> { level: 'INFO', message: 'Hello, World!' }

[Formatting](http://nodejs.org/api/util.html#util_util_format_format):

    log('INFO', 'CC Charge amount=%d username=%s', 12.85, 'thomasc');
    // emits ---> { level: 'INFO', message: 'CC Charge amount=12.85 username=thomasc' }

Non-string message arguments:

    log('INFO', 'IP Whitelist Accept', { remote_ip: remote_ip });
    // emits ---> { level: 'INFO', message: 'IP Whitelist Accept remote_ip=123.123.123.123' }

With censorship:

    const log = require('ssi-logger');

    const options = {
        logger: {
            censor: [
                'card_number',      // can contain property names
                /pass(word)?/       // and/or regular expressions
            ],
            transports: {
                syslog: {facility: "LOG_LOCAL5", level: "INFO"},
                console: {},
            }
        }
    };

    log.open(options.logger.transports);
    log.censor(options.logger.censor);

    log('INFO', { first_name: 'John', last_name: 'Doe', card_number: '1234123412341234' });
    // emits ---> { level: 'INFO', message: 'first_name=John last_name=Doe card_number=[redacted]' }


Return value:

    if (err) {
        const human_readble_error_string = log('ERROR', err);
        displayError(human_readble_error_string);
        callback(err);
    }

Logging to a file with daily log rotation:

    const FileStreamRotator = require('file-stream-rotator');
    const log = require('ssi-logger');
    const path = require('path');

    const logfile = FileStreamRotator.getStream({
        filename: path.join(__dirname, 'application-%DATE%.log'),
        frequency: 'daily',
        verbose: false,
        date_format: 'YYYY-MM-DD'
    });

    const options = {
        logger: {
            transports: {
                stream: { stream: logfile },
            }
        }
    };

    log.open(options.logger.transports);

    log('INFO', 'This message gets logged to a file');

Setting defaults that are included in every log message:

    const app = express();

    app.use(function loggingConfig(req, res, next) {
        req.log = log.defaults({
            request_id: uuid.v1(),
            client_ip: req.ip
        });
    });

    app.get('/users/:uid', function getRoot(req, res) {
        req.log('INFO', 'User Get', req.params);
        // emits ---> { level: 'INFO', message: 'User Get uid=thomasc request_id=e3aec5a8-12af-11e6-a148-3e1d05defe78 client_ip=127.0.0.1' }

        res.render('user', db.getUser(req.params.uid));
    });

    app.listen(3000);

Convenience methods:

    log.info('Hello, World!');
    // emits ---> { level: 'INFO', message: 'Hello, World!' }

    log.alert('/dev/lp0 on fire!');
    // emits ---> { level: 'ALERT', message: '/dev/lp0 on fire!' }

Standard Log Levels (highest to lowest):

    EMERG, ALERT, CRIT, ERROR, WARN, NOTICE, INFO, DEBUG

## Configuration

SSi Logger will look system wide configuration files in several places, reading each and overriding previous value.  The configuration files need not exist as the application can override them (see `log.censor()` and `log.open()` below).  The load order is:

* internal defaults
* `./ssi-logger.conf.defaults` (install directory)
* `/etc/ssi-logger.conf`
* `/etc/ssi-logger.conf.local`
* `/usr/local/etc/ssi-logger.conf`
* `/usr/local/etc/ssi-logger.conf.local`

The general structure of a configuration file is an JSON object containing:

* `messageMaxLength`: maximum message length. Any message longer than this limit is truncated to this limit. Default `8192`.
* `censor`: an array of key field names to censor.
* `transports`: a collection of `ssi-logger` transports to give `log.open()`.


## Transports

Log messages are emitted as `log` events. Event listeners should be installed to receive the events and send them over
the appropriate transport. SSi Logger provides a couple of common transports.

Here's a setup example for a project using multiple transports to log messages.  Depending on the value of `level` or `logLevel`, log messages may or may not go to syslog or AMQP.  Here `INFO` means that log messages with levels up to and including `INFO` are logged, i.e. `DEBUG` messages are not logged; likewise up to and including `ERROR`, would exclude `INFO` and `DEBUG`.

    // Logging defaults.
    const options = {
        logger: {
            transports: {
                amqp: {url: "amqp://user:password@example.com/virt_host", facility: "LOG_USER", level: "ERROR"},
                syslog: {facility: "LOG_LOCAL5", level: "INFO"},
                console: {timestamp: true},
            }
        }
    };
    
    ...
    
    // Enable different transports depending on NODE_ENV.
    _.defaultsDeep(options, {
        logger: {
            transports: {
                amqp: {enable: process.env.NODE_ENV === 'production'},
                console: {enable: process.env.NODE_ENV !== 'production'},
                syslog: {enable: process.env.NODE_ENV !== 'production'},
            }
        }
    });
    
    log.open(options.logger.transports);
    
    log.info('Ready to rock!');

This is a very powerful pattern. It allows for many different combinations of actions. For example, one could write
a transport such that a LOG_ALERT message about the database being down will trigger an e-mail to go out to the sysadmin.


## API

### log(level, format, args ...)

**Parameters**

* `level`: log level string, one of `EMERG`, `ALERT`, `CRIT`, `ERROR`, `WARN`, `NOTICE`, `INFO`, `DEBUG`.
* `format`: a log message format string.
* `args`: the `format` string will consume `args` for each % argument in the string.  Remaining arguments are appended to the log message, with objects and arrays beening flattened into key=value pairs.

#### log.emerg(format, args ...)
#### log.alert(format, args ...)
#### log.crit(format, args ...)
#### log.error(format, args ...)
#### log.warn(format, args ...)
#### log.notice(format, args ...)
#### log.info(format, args ...)
#### log.debug(format, args ...)

Convenience functions.

### log.censor()

Returns a list of fields that are presently being censored from all log messages.

Example:

    // get the list of censored fields
    console.log(log.censor());
    // prints --> [ 'card_number', /pass(word)?/ ]


### log.censor(arr)

Sets the list of fields to censor from all log messages.  Any number of fields may be censored.  This is useful when logging request objects to avoid accidentally logging a credit card number, password, or other sensitive information.

**Parameters**

* `arr`: an array which may contain any combination of strings and regular expression objects. The strings and regular expressions are used to match against the log message. To turn off censorship, call this function with an empty array `[]`.

**Example**

    // set the list
    log.censor([ 'card_number', /pass(word)?/ ]);

    log('INFO', 'first_name=John last_name=Doe card_number=1234123412341234 password=pizza');
    log('INFO', 'first_name=%s last_name=%s card_number=%s password=%s', first_name_var, last_name_var, card_number_var, password_var);
    log('INFO', { first_name: 'John', last_name: 'Doe', card_number: '1234123412341234', password: 'pizza' });

    // each one above emits the same thing -->
    // { level: 'INFO', message: 'first_name=John last_name=Doe card_number=[redacted] password=[redacted]' }


### log.close(optDone)

Close the transports like `syslog` and `amqp`.

**Parameters**

* `optDone`: optional callback once all the transports have closed.


### log.open(transportOptions[, userTransports])

**Parameters**

* `transportOptions`: contains one or more transports to configure
   - `amqp`: optional AMQP transport options, see below
   - `console`: optional console transport options, see below
   - `stream`: optional stream transport options, see below
   - `syslog`: optional SysLog transport options, see below
   - `user_transport`: optional options for a `user_transport`

* `userTransports`: an object with one or more user transport functions.  For example:
```
    const Transport = require('log').Transport;

    class TripwireTransport extends Transport {
        log(log_event) {
            options.patterns.forEach((pattern) => {
                if (pattern.test(log_event.message)){
                    console.log("Run for the hills.");
                    process.exit(1);
                }
            });
        }
    };

    log.open({
        console: {enable: process.env.NODE_ENV !== 'production'},
        syslog: {enable: process.env.NODE_ENV === 'production'},
        tripwire: {enable: process.env.NODE_ENV !== 'production'},
    }, {
        tripwire: TripwireTransport,
    });
```

### Log Event

The `log_event` passed to log event transport handlers is an object with the following fields:

`log_event`:
  - `version`: Version number following https://semver.org/ guidelines.  Currently `1.1.0`.
  - `created`: JavaScript Date when the event occurred.
  - `host`: Host name string.
  - `level`: Log level string.
  - `message`: Formatted log message.
  - `data`: An array of the censored log() arguments.
  - `eid`: opaque log event ID.


### Available Transports

Here are the available transports.

#### lib/Transport

The base class for pre-defined and user transports.

```
class Transport {
    constructor(options) {}

    // Return true to log the event; otherwise false to ignore.
    filter(event) {}

    log(event) {}

    // Close the transport.  Optional callback when done.
    end(optDone) {}
}
```

**Options**
  - `level`: optional log level where only messages of this level or higher are published (ordered high to low) `EMERG`, `ALERT`, `CRIT`, `ERROR`, `WARN`, `NOTICE`, `INFO`, `DEBUG`; default `DEBUG`.


#### lib/transports/amqp

Log large JSON messages to an AMQP server.  In the event of a connection or channel error, the error stack is saved to `$TMPDIR/$PROCESS_NAME.stack` and attempt to reconnect if so configured.  If  `$TMPDIR` is undefined, the default is `/var/tmp`.

**Parameters**

`amqp`:
  - `enable`: `true` if this transport is enabled; default `true`.
  - `url`: an AMQP url, eg. `amqp://guest:guest@localhost/`,
  - `socketOptions`: optional object of socket options; default `{}`
    * `noDelay` sets `TCP_NODELAY` (booloan).
    * `cert` client certificate (buffer).
    * `key` client key (buffer).
    * `passphrase` - passphrase for private key
    * `ca` - array of CA certificates (array of buffer).
  - `exchangeName`: optional exchange name where to publish log messages; default `logger`
  - `exchangeOptions`: options for the exchange.
    * `durable`: exchange persists across server restarts; default `true`.
    * `autoDelete`: exchange deletes itself when there are no bindings; default `false`.
  - `reconnect`: options for re-connection:
    * `retryTimeout`: how long in seconds to continue attempting re-connections before emitting an `error` event; default 0.
    * `retryDelay`: how long in seconds to wait between re-connection attempts; default 5.
  - `routeKeyPrefix`: prefix for the routing key; default "log".  The routing key format is "prefix.proc_name.facility.level".
  - `level`: optional log level where only messages of this level or higher are published (ordered high to low) `EMERG`, `ALERT`, `CRIT`, `ERROR`, `WARN`, `NOTICE`, `INFO`, `DEBUG`; default `INFO`.
  - `facility`: optional syslog facility name, one of `AUTH`, `CRON`, `DAEMON`, `KERN`, `LOCAL0`, `LOCAL1`, `LOCAL2`, `LOCAL3`, `LOCAL4`, `LOCAL5`, `LOCAL6`, `LOCAL7`, `LPR`, `MAIL`, `NEWS`, `SYSLOG`, `USER`, `UUCP`; default `LOCAL0`.  Note the facility name in the AMQP log message is informational only.
  - `format`: one of `text`, `json`; default `text`.  `text` sends text log message with all the arguments flattened out into message.  `json` formats the message only those % arguments specified, the remaining unused are pased as JSON.
  - `traceLevel`: 0 = disable, 1 = connection, 2 = verbose; default 0.
  - `chunkSize`: split long messages into messages no longer than `chunkSize`. Default `8192`.

Example:

    log.open({
        amqp: {
            url: 'amqp://guest:somepassword@example.com/virtual_host',
            exchangeName: 'logger'
       }
    });

**Process Events**

`log_amqp_transport_gone`: When the AMQP connection is closed (server shutdown, forced disconnect from UI, unexpected disconnect) and reconnection is disabled or times out while trying to reconnect, then `log_amqp_transport_gone` is emitted to the `process`.


#### lib/transports/console

**Parameters**

`console`:
  - `enable`: `true` if this transport is enabled; default `true`.
  - `color`: `true` to enable color coded log messages; defaults `true`.
  - `stderr`: `true` to direct log messages to standard error, otherwise standard output; default `false`.
  - `timestamp`: `true` to prepend ISO 8601 timestamp to all console messages; default `false`.
  - `level`: optional log level where only messages of this level or higher are published (ordered high to low) `EMERG`, `ALERT`, `CRIT`, `ERROR`, `WARN`, `NOTICE`, `INFO`, `DEBUG`; default `DEBUG`.
  - `chunkSize`: split long messages into messages no longer than `chunkSize`. Default `8192`.

Logs all messages to the console in the form:

    [LEVEL] message text

or when `options.timestamp` is true:

    2018-03-26T15:07:27Z [LEVEL] message text

Colors can also be disabled at runtime with the `--no-color` command line option.

    log.open({
        console: {colour: true, timestamp: true, stderr: true}
    });


#### lib/transports/stream ###

**Parameters**

`stream`:
  - `enable`: `true` if this transport is enabled; default `true`.
  - `color`: `true` to enable color coded log messages; defaults `true`.
  - `stream`: `Stream` object to write log messages, one per line.
  - `timeout`: `true` to prepend ISO 8601 timestamp to all console messages; default `true`.
  - `level`: optional log level where only messages of this level or higher are published (ordered high to low) `EMERG`, `ALERT`, `CRIT`, `ERROR`, `WARN`, `NOTICE`, `INFO`, `DEBUG`; default `DEBUG`.
  - `chunkSize`: split long messages into messages no longer than `chunkSize`. Default `8192`.

Logs all messages to the console in the form:

    [LEVEL] message text

or when `options.timestamp` is true:

    2018-03-26T15:07:27Z [LEVEL] message text

Colors can also be disabled at runtime with the `--no-color` command line option.

    log.open({
        stream: {enable: true, stream: logfile}
    });


#### lib/transports/syslog ###

**Parameters**

`syslog`:
  - `enable`: `true` if this transport is enabled; default `true`.
  - `facility`: one of `LOG_AUTH`, `LOG_CRON`, `LOG_DAEMON`, `LOG_KERN`, `LOG_LOCAL0`, `LOG_LOCAL1`, `LOG_LOCAL2`, `LOG_LOCAL3`, `LOG_LOCAL4`, `LOG_LOCAL5`, `LOG_LOCAL6`, `LOG_LOCAL7`, `LOG_LPR`, `LOG_MAIL`, `LOG_NEWS`, `LOG_SYSLOG`, `LOG_USER`, `LOG_UUCP`; default `LOG_LOCAL0`.
  - `level`: one of (ordered high to low) `EMERG`, `ALERT`, `CRIT`, `ERROR`, `WARN`, `NOTICE`, `INFO`, `DEBUG`; default `INFO`.
  - `chunkSize`: split long messages into messages no longer than `chunkSize`. Default `8192`.


Examples:

    // default minimum log level to INFO
    log.open({
        syslog: {facility: 'LOG_LOCAL1'}
    });

    // set minimum log level to ERROR
    log.open({
        syslog: {facility: 'LOG_LOCAL2', level: 'ERROR'}
    });

    // set minimum log level to DEBUG
    log.open({
        syslog: {facility: 'LOG_LOCAL3', level: 'DEBUG'}
    });

### log.defaults(...)

Returns a new curried `log()` function with baked in parameters that are included in all log messages.

Example:

    const mylog = log.defaults({ request_id: '7423927D-6F4E-43FE-846E-C474EA3488A3' }, 'foobar');

    mylog('INFO', 'I love golf!');

    // emits --> { level: 'INFO', message: 'I love golf! request_id=7423927D-6F4E-43FE-846E-C474EA3488A3 foobar' }


## Configuring syslog on Mac OS X

Edit `/etc/syslog.conf`:

    sudo -e /etc/syslog.conf

Add the following line to `/etc/syslog.conf`:

    local5.*                        /var/log/local5.log

Send `syslogd` the HUP signal:

    sudo killall -HUP syslogd

Test with `logger`:

    logger -p local5.info "Test"
    tail /var/log/local5.log

## Configuring rsyslog on Debain

Edit `/etc/rsyslog.conf`:

    sudo -e /etc/rsyslog.conf

Add the following line to `/etc/rsyslog.conf`:

    local5.*                        /var/log/local5.log

Restart `rsyslog`:

    sudo service rsyslog restart

Test with `logger`:

    logger -p local5.info "Test"
    tail /var/log/local5.log


## Developing a custom Transport

Implementing a custom transport involves writing an event listener that receives log events.
At present, the log events are objects that have `level` and `message` properties.

    function smsTransport(evt) {
        // evt = { level: 'EMERG', message: '/dev/lp0 on fire!' }

        switch (evt.level) { // only act on important log messages
            case 'EMERG':
            case 'ALERT':
            case 'CRIT':
                twilloClient.messages.create({
                    from: ssiSmsNumber,
                    to: tcSmsNumber,
                    body: '[' + evt.level + ']' + evt.message
                });
                break;
        }
    }

    process.on('log', smsTransport);

    if (printerOnFire) {
        log('EMERG', '/dev/lp0 on fire!');
    }

## Testing

This only needs to be done once in order to configure the `amqpTransport` tests:

    npm run preinstall
    vi test/ssi-logger.conf             # edit credentials

There is an automated test suite:

    npm test

There are several optional tests that can be run with:

    npm run testall

As well as several manual tests:

    cd test
    node manual-colors-test.js
    node manual-colors-test.js --no-color
    node manual-test.js && tail /var/log/local5.log
    node manual-amqp.js

## Logging Best Practices

- log anything were no change to persistent data nor state was made at the `DEBUG` level. Log messages such as `Getting DB connection` fall into this category.
- log changes to any persistent data (Create/Update/Delete operations) at the `INFO` level.
- always include IDs and other references in log messages.
- use a consistent format so that searches can find things quickly. For example: `NOUN VERB ...` (e.g. `ACCOUNT GET account_id=5000000`).
- when state is being changed, include the changes in the log message.
- avoid duplicating log messages as it makes troubleshooting more difficult..
- log errors in one place, typically at the outermost error handler. Only the caller can decide what is relevant to log. For example, in the error handler middleware in the case of a REST API.
- use a correlation ID in each log message related to the same request to make execution easier to trace.
- use the `censor()` feature to censor sensitive information such as credit card numbers, passwords, and keys.
- think of the person dealing with the problem when constructing error log messages. Consider providing instructions for fixing the problem in the log message and/or re-running failed commands. For example, include a `curl` command in the log message that the troubleshooter can use to re-run a failed request.
- log actions after they occur.

## License

See [LICENSE.md](https://github.com/ssimicro/ssi-logger/blob/master/LICENSE.md).