@abeai/node-logging

Abe AI logging package

Usage no npm install needed!

<script type="module">
  import abeaiNodeLogging from 'https://cdn.skypack.dev/@abeai/node-logging';
</script>

README

node-logging

Node package to provide functionality around logging / monitoring of node services in Abe AI's ecosystem by using pino and Elastic APM.

Setup

npm install @abeai/node-logging --save

'use strict';

// Add this line before requiring any other modules!
require('@abeai/node-logging').init({ appName: 'loggingExampleApp' });

const express = require('express');
const logger = require('@abeai/logging').logger;
const loggingMiddleware = require('@abeai/logging').expressMiddleware;

const app = express();

// The request handler middleware has to run before any logging occurs
loggingMiddleware.requestHandler(app);

app.get('/', (req, res) => {
  req.ctx.logger.info('Hello World with Correlation ID!');

  res.send('Hello World!');
});

// The error handler middleware has to be declared last
loggingMiddleware.errorHandler(app);

app.listen(3000, () => logger.info(`Listening on port 3000`));

Express Middlewares

requestHandler

const loggingMiddleware = require('@abeai/logging').expressMiddleware;

...

// The request handler middleware has to run before any logging occurs
loggingMiddleware.requestHandler(app);

This middleware initializes the context with header attributes from the request, assigns the context to the request and response object, and logs basic request/response information. The middleware should be used as early as possible, before any logging occurs.

errorHandler

const loggingMiddleware = require('@abeai/logging').expressMiddleware;

...

// The error handler middleware has to be declared last
loggingMiddleware.errorHandler(app);

This middleware logs any uncaught exceptions with relevant request information. The middleware has to be declared last.

Socket.io Middlewares

eventHandler

const loggingMiddleware = require('@abeai/logging').Socket.IOMiddleware;

...

io.on('connection', (socket) => {
  // The event handler middleware has to run before any logging occurs
  loggingMiddleware.eventHandler(socket);

  socket.on('myEvent', (ctx, arg1, arg1) => {
    ...
  });
});

This middleware initializes and assigns the context to the event, and logs basic event information. The middleware should be used as early as possible, before any logging occurs.

errorHandler

const loggingMiddleware = require('@abeai/logging').Socket.IOMiddleware;

...

io.on('connection', (socket) => {
  // The event handler middleware has to run before any logging occurs
  loggingMiddleware.eventHandler(socket);

  socket.on('myEvent', (ctx, arg1, arg1) => {
    try {
       ...
    } catch (error) {
       loggingMiddleware.errorHandler(ctx, error);
    }
  });
});

This middleware logs any uncaught exceptions with relevant event information. The middleware has to be declared last.

Logging

Initialization

require('@abeai/node-logging').init({ appName: 'myAppName' });

Configuration Attributes:

  • appName: Is used to namespace log data which should be indexed. If not set, uses the following variables as alternatives: process.env.LOGGER_APP_NAME || process.env.ELASTIC_APM_SERVICE_NAME || process.title
  • level
  • prettyPrint
  • ignoreUrls: List of strings and/or regular expressions to match request URL, or a function to decide on behavior. Successful requests won't be logged if request URL matches. Unsucceful requests are always logged.
  • parseContextRequestHeaders: If false, context request headers will not be parsed. If true, context request headers will be parsed for all requests. If list is given, context request headers will be parsed based of if one of the given strings or regular expressions matches the request URL. If function, will be called with request object to decide on behavior. Default is true.
  • requireRequestCorrelationId: Will log a warning if no correlation ID is found on the request. Though a correlation I is still generated on-the-line in this case. Valid values are boolean, a list of strings and/or regular expressions to match request URL, or a function to decide on behavior. Default is true.
  • addResponseReferenceId: If true, the correlation ID will be added as the header Abe-AI-Reference-ID to the response. This is useful for consumers of our external APIs. Default is false.
  • logRequestBody
  • logResponseBody
  • stringifyRequestBody
  • stringifyResponseBody
  • stringifyUnindexedData
  • sentryDSN
  • sendToSentryLevels
  • elasticApmServerUrl
  • elasticApmServiceName
  • elasticApmServiceNameIgnoreUrls: List of strings and/or regular expressions to match request URL which should be ignored by Elastic APM. ignoreUrls is used as fallback.
  • redactionPaths: List of strings, describing the nested location of a key in an object. The path can be represented in dot notation, a.b.c, and/or bracket notation a[b[c]], a.b[c], a[b].c. Paths also supports the asterisk wildcard (*) to redact all keys within an object. For instance a.b.* applied to the object {a: b: {c: 'foo', d: 'bar'}} will result in the redaction of properties c and d in that object ({"a": "b": {"c": "[Redacted]", "d": "[Redacted]"}}).
  • redactionCensor: Any type, for instance an object like {redacted: true} is allowed, as is null. Explicitly passing undefined as the censor will in most cases cause the property to be stripped from the object. Edge cases occur when an array key is redacted, in which case null will appear in the array (this is ultimately a nuance of JSON.stringify, try JSON.stringify(['a', undefined, 'c'])). Can also accept a function. This is helpful in cases where you want to redact dynamically instead of a fixed value. A common use case could be to mask partially (e.g. { test: 1234567890 } => { "test": "xxxxxx7890" }). Check the tests to see this in action. Default is '[redacted]'.
  • disableCryptoRedaction: Disables automatic redaction of encrypted model fields sent to the logger.

Usage

For non-context related logging (e.g. no correlation ID) you can use the logger directly:

const logger = require('@abeai/logging').logger;

If you're in a request (or Socket.IO event) cycle, you should use the logger on the ctx object which is available on the request, response, and event object:

Express

app.get('/', (req, res) => {
  req.ctx.logger.info('Hello World with Correlation ID!');

  res.send('Hello World!');
});

Socket.IO

const loggingMiddleware = require('@abeai/logging').Socket.IOMiddleware;

...

io.on('connection', (socket) => {
  // The event handler middleware has to run before any logging occurs
  loggingMiddleware.eventHandler(socket);

  socket.on('myEvent', (ctx, arg1, arg1) => {
    ctx.logger.info('myEvent with Correlation ID!');
  });
});

Message Logging

The log levels are the same as pino's. Though the function signature is a bit different:

  • logger.fatal
  • logger.error
  • logger.warning
  • logger.info
  • logger.debug
  • logger.trace

All functions can take just just a message, or a message with data. Additionally fatal, error, and warning support passing in an error object as a single argument.

The following data attributes are supported:

  • unindexed: Data which should be encoded as a JSON string to avoid indexing. It will be added to the top-level of the log message.
  • indexed: Data which should be encoded as JSON for indexing. It will be scoped by the logger name on the top-level of the log message avoid structure conflicts with other services.
  • err: Error object which should be serialized.

The following option attributes are supported:

  • annotations: See annotations below

Example:

logger.info('log this');
logger.info('log with raw data', {unindexed: {aLotOfData: ...}}, {annotations: {platformVisible: []}});
logger.info('log with json data', {indexed: {dataWhichShouldBeIndexed: ...}});
logger.info('log with data', {unindexed: {aLotOfData: ...}, indexed: {dataWhichShouldBeIndexed: ...}});
logger.error(new Error('my error'));
logger.error('a separate error message', new Error('my error'));

Log Event Annotations

platformVisible

To specify that a log event and/or some data on that event is sutible and should be visible within the platform UI the platformVisible annotation can be used.

The following values are supported:

  • []: The log event and no data is visible to the platform
  • ['uninexed/indexed.glob.based.key']: The log event and the data keys specified globs are visible to the platform

Example:

logger.info('log with json data', {indexed: {dataWhichShouldBeIndexed: ...}}, {
    annotations: {
        platformVisible: []
    }
});
logger.info('log with data', {unindexed: {aLotOfData: ...}, indexed: {smallString: 't', dataWhichShouldBeIndexed: ...}}, {
    annotations: {
        platformVisible: ['unindexed.aLotOfData', 'indexed.smallString']
    }
});

Context Management

The context can be either created manually via require('@abeai/node-logging').initContext or it will be automatillcay intialized by the Express or Socket.IO middleware.

The context supports the following attributes:

  • logger: Logger instance associated with the context.
  • state: Dictionary which can hold application relevant data.

The context state supports the following build-in attributes for log annotations and request header handling:

  • correlationId: Correlation ID of current request chain. This attribute is always available and can't be set or merged.
  • channelType: Channel type related to current request chain. This attribute is optional.
  • channelId: Channel ID related to current request chain. This attribute is optional.
  • channelIdentityId: Channel Identity ID related to current request chain. This attribute is optional.
  • agentId: Agent ID related to current request chain. This attribute is optional.
  • agentName: Agent Name related to current request chain. This attribute is optional.
  • userId: User ID related to current request chain. This attribute is optional.
  • cuiConfigId: CUI Config ID related to current request chain. This attribute is optional.
  • cuiUserId: CUI User ID related to current request chain. This attribute is optional.
  • testRun: Test run related to current request chain. This attribute is optional.

Context Propagation for Inter-Service Communication

The context provides the attrgiute ctx.requestHeaders which returns a list of requests headers which needs to be merged into the headers of a requests to another Abe AI service.

The following headers are supported:

  • Abe-AI-Correlation-ID
  • Abe-AI-Channel-Type
  • Abe-AI-Channel-ID
  • Abe-AI-Channel-Identity-ID
  • Abe-AI-Agent-ID
  • Abe-AI-Agent-Name
  • Abe-AI-User-ID
  • Abe-AI-CUI-Config-ID
  • Abe-AI-CUI-User-ID
  • Abe-AI-Test-Run

Example:

rp({
    method: 'GET',
    uri: `${config.anotherAbeAiServiceUrl}/coolStuff`,
    headers: Object.assign({
        'My-Header': 'stuff',
    }, ctx.requestHeaders)
})
    .then((response) => {
        ...
    })
;

Log Output Structure

The structure is based on pino with some additions:

Normal Message

logger.info('log this');

Output:

{
  "abeServiceLogging": 1,
  "correlationId": "111e4567-e89b-12d3-a456-426655441111",
  "channelType": "GOOGLE",
  "channelId": "222e4567-e89b-12d3-a456-426655442222",
  "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
  "agentId": "444e4567-e89b-12d3-a456-4266554444444",
  "agentName": "Demo FI",
  "userId": "555e4567-e89b-12d3-a456-426655445555",
  "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
  "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
  "v": 1,
  "pid": 94473,
  "hostname": "MacBook-Pro-3.home",
  "time": 1459529098958,
  "level": 30,
  "msg": "log this"
}

Message With Raw Data

logger.info('log with raw data', {unindexed: {aLotOfData: ...}});

Output:

{
  "abeServiceLogging": 1,
  "correlationId": "111e4567-e89b-12d3-a456-426655441111",
  "channelType": "GOOGLE",
  "channelId": "222e4567-e89b-12d3-a456-426655442222",
  "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
  "agentId": "444e4567-e89b-12d3-a456-4266554444444",
  "agentName": "Demo FI",
  "userId": "555e4567-e89b-12d3-a456-426655445555",
  "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
  "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
  "v": 1,
  "pid": 94473,
  "hostname": "MacBook-Pro-3.home",
  "time": 1459529098958,
  "level": 30,
  "msg": "log with raw data",
  "data": {
    "unindexed": "{\"aLotOfData\": ...}"
  }
}

Message With JSON Data

logger.info('log with json data', {indexed: {dataWhichShouldBeIndexed: ...}});

Output:

{
    "abeServiceLogging": 1,
    "correlationId": "111e4567-e89b-12d3-a456-426655441111",
    "channelType": "GOOGLE",
    "channelId": "222e4567-e89b-12d3-a456-426655442222",
    "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
    "agentId": "444e4567-e89b-12d3-a456-4266554444444",
    "agentName": "Demo FI",
    "userId": "555e4567-e89b-12d3-a456-426655445555",
    "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
    "v": 1,
    "pid": 94473,
    "hostname": "MacBook-Pro-3.home",
    "time": 1459529098958,
    "level": 30,
    "msg": "log with raw data",
    "data": {
        "myAppName": {
            "dataWhichShouldBeIndexed": ...
        }
    }
}

Message With Raw Data And JSON Data

logger.info('log with data', {unindexed: {aLotOfData: ...}, indexed: {dataWhichShouldBeIndexed: ...}});

Output:

{
    "abeServiceLogging": 1,
    "correlationId": "111e4567-e89b-12d3-a456-426655441111",
    "channelType": "GOOGLE",
    "channelId": "222e4567-e89b-12d3-a456-426655442222",
    "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
    "agentId": "444e4567-e89b-12d3-a456-4266554444444",
    "agentName": "Demo FI",
    "userId": "555e4567-e89b-12d3-a456-426655445555",
    "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
    "v": 1,
    "pid": 94473,
    "hostname": "MacBook-Pro-3.home",
    "time": 1459529098958,
    "level": 30,
    "msg": "log with raw data",
    "data": {
        "unindexed": "{\"aLotOfData\": ...}",
        "myAppName": {
            "dataWhichShouldBeIndexed": ...
        }
    }
}

Message With Additional Error Object

logger.error('a separate error message', new Error('my error'));

Output:

{
  "abeServiceLogging": 1,
  "correlationId": "111e4567-e89b-12d3-a456-426655441111",
  "channelType": "GOOGLE",
  "channelId": "222e4567-e89b-12d3-a456-426655442222",
  "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
  "agentId": "444e4567-e89b-12d3-a456-4266554444444",
  "agentName": "Demo FI",
  "userId": "555e4567-e89b-12d3-a456-426655445555",
  "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
  "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
  "v": 1,
  "pid": 94473,
  "hostname": "MacBook-Pro-3.home",
  "time": 1459529098958,
  "level": 50,
  "msg": "a separate error message",
  "err": {
    "type": "Error",
    "message": "my error",
    "stack": "Error: an error\n    at Object.<anonymous> (/Users/davidclements/z/nearForm/pino/example.js:14:12)\n    at Module._compile (module.js:435:26)\n    at Object.Module._extensions..js (module.js:442:10)\n    at Module.load (module.js:356:32)\n    at Function.Module._load (module.js:311:12)\n    at Function.Module.runMain (module.js:467:10)\n    at startup (node.js:136:18)\n    at node.js:963:3"
  }
}

Error Object

logger.error(new Error('my error'));

Output:

{
  "abeServiceLogging": 1,
  "correlationId": "111e4567-e89b-12d3-a456-426655441111",
  "channelType": "GOOGLE",
  "channelId": "222e4567-e89b-12d3-a456-426655442222",
  "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
  "agentId": "444e4567-e89b-12d3-a456-4266554444444",
  "agentName": "Demo FI",
  "userId": "555e4567-e89b-12d3-a456-426655445555",
  "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
  "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
  "v": 1,
  "pid": 94473,
  "hostname": "MacBook-Pro-3.home",
  "time": 1459529098958,
  "level": 50,
  "msg": "my error",
  "err": {
    "type": "Error",
    "message": "my error",
    "stack": "Error: an error\n    at Object.<anonymous> (/Users/davidclements/z/nearForm/pino/example.js:14:12)\n    at Module._compile (module.js:435:26)\n    at Object.Module._extensions..js (module.js:442:10)\n    at Module.load (module.js:356:32)\n    at Function.Module._load (module.js:311:12)\n    at Function.Module.runMain (module.js:467:10)\n    at startup (node.js:136:18)\n    at node.js:963:3"
  }
}

Successful Request

Output:

{
  "abeServiceLogging": 1,
  "correlationId": "111e4567-e89b-12d3-a456-426655441111",
  "channelType": "GOOGLE",
  "channelId": "222e4567-e89b-12d3-a456-426655442222",
  "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
  "agentId": "444e4567-e89b-12d3-a456-4266554444444",
  "agentName": "Demo FI",
  "userId": "555e4567-e89b-12d3-a456-426655445555",
  "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
  "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
  "v": 1,
  "pid": 94473,
  "hostname": "MacBook-Pro-3.home",
  "time": 1459529098958,
  "level": 30,
  "msg": "Request completed",
  "req": {
    "method": "POST",
    "url": "/?test=1",
    "headers": {
      "host": "localhost:3000",
      "user-agent": "curl/7.54.0",
      "content-type": "application/json",
      "accept": "application/json",
      "content-length": "10"
    },
    "remoteAddress": "::1",
    "remotePort": 56330,
    "body": "{\"test\":1}"
  },
  "res": {
    "statusCode": 200,
    "header": "HTTP/1.1 200 OK\r\nX-Powered-By: Express\r\nAbe-AI-Reference-ID: cda86902-461e-472a-ae2c-396c5bdc55da\r\nContent-Type: application/json; charset=utf-8\r\nContent-Length: 14\r\nETag: W/\"e-CdsQPLbJIMgXo5pizELzDY/989E\"\r\nDate: Thu, 03 May 2018 12:31:13 GMT\r\nConnection: keep-alive\r\n\r\n",
    "body": "\"Hello World!\""
  },
  "responseTime": 5
}

Unsuccessful Request With Error Object

throw new Error('my error');

Output:

{
    "abeServiceLogging": 1,
    "correlationId": "111e4567-e89b-12d3-a456-426655441111",
    "channelType": "GOOGLE",
    "channelId": "222e4567-e89b-12d3-a456-426655442222",
    "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
    "agentId": "444e4567-e89b-12d3-a456-4266554444444",
    "agentName": "Demo FI",
    "userId": "555e4567-e89b-12d3-a456-426655445555",
    "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
    "v": 1,
    "pid": 94473,
    "hostname": "MacBook-Pro-3.home",
    "time": 1459529098958,
    "level": 50,
    "msg": "Request errored",
    "err": {
        "type": "Error",
        "stack": "Error: my error\n    at Object.<anonymous> (/Users/davidclements/z/nearForm/pino/example.js:14:12)\n    at Module._compile (module.js:435:26)\n    at Object.Module._extensions..js (module.js:442:10)\n    at Module.load (module.js:356:32)\n    at Function.Module._load (module.js:311:12)\n    at Function.Module.runMain (module.js:467:10)\n    at startup (node.js:136:18)\n    at node.js:963:3"
    }
    "req":{
        "method":"GET",
        "url":"/error-in-promise",
        "headers":{
            "host":"localhost:3000",
            "user-agent":"curl/7.54.0",
            "content-type":"application/json",
            "accept":"application/json"
        },
        "remoteAddress":"::1",
        "remotePort":56332
    },
    "res":{
        "statusCode":500,
        "header":"HTTP/1.1 500 Internal Server Error\r\nX-Powered-By: Express\r\nAbe-AI-Reference-ID: 7fd0d64d-fff9-4794-a618-02496900294e\r\nContent-Type: application/json; charset=utf-8\r\nContent-Length: 20\r\nETag: W/\"14-FJXd+uz64FdKH++J0y7A2OERZ+s\"\r\nDate: Thu, 03 May 2018 12:31:13 GMT\r\nConnection: keep-alive\r\n\r\n",
        "body":"{\"error\":\"my error\"}"
    },
    "responseTime":1
}

Unsuccessful Request Without Error Object

throw 'my error';

Output:

{
  "abeServiceLogging": 1,
  "correlationId": "111e4567-e89b-12d3-a456-426655441111",
  "channelType": "GOOGLE",
  "channelId": "222e4567-e89b-12d3-a456-426655442222",
  "channelIdentityId": "333e4567-e89b-12d3-a456-426655443333",
  "agentId": "444e4567-e89b-12d3-a456-4266554444444",
  "agentName": "Demo FI",
  "userId": "555e4567-e89b-12d3-a456-426655445555",
  "cuiConfigId": "666e4567-e89b-12d3-a456-426655446666",
  "cuiUserId": "666e4567-e89b-12d3-a456-426655447777",
  "v": 1,
  "pid": 94473,
  "hostname": "MacBook-Pro-3.home",
  "time": 1459529098958,
  "level": 50,
  "msg": "Request errored",
  "req": {
    "method": "GET",
    "url": "/error-in-promise",
    "headers": {
      "host": "localhost:3000",
      "user-agent": "curl/7.54.0",
      "content-type": "application/json",
      "accept": "application/json"
    },
    "remoteAddress": "::1",
    "remotePort": 56332
  },
  "res": {
    "statusCode": 500,
    "header": "HTTP/1.1 500 Internal Server Error\r\nX-Powered-By: Express\r\nAbe-AI-Reference-ID: 7fd0d64d-fff9-4794-a618-02496900294e\r\nContent-Type: application/json; charset=utf-8\r\nContent-Length: 20\r\nETag: W/\"14-FJXd+uz64FdKH++J0y7A2OERZ+s\"\r\nDate: Thu, 03 May 2018 12:31:13 GMT\r\nConnection: keep-alive\r\n\r\n",
    "body": "{\"error\":\"my error\"}"
  },
  "responseTime": 1
}

Deployment

The package requires the following env vars:

ELASTIC_APM_SERVICE_NAME=<service name>
ELASTIC_APM_SECRET_TOKEN=<token>
ELASTIC_APM_SERVER_URL=<server url>

Redaction

This library supports automatic DB model redaction by attempting to call the redactSensitiveData() function on all objects in the payload sent to Kibana during stringification.