@abeai/logging

Abe AI logging package

Usage no npm install needed!

<script type="module">
  import abeaiLogging from 'https://cdn.skypack.dev/@abeai/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/logging elastic-apm-node --save-exact

// Add those two line before requiring any other modules!
require('elastic-apm-node').start({
    active: process.env.ELASTIC_APM_ACTIVE === 'true',
});
require('@abeai/logging').configure({appName: 'loggingExampleApp'});

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

const app = express();

// This middleware has to run before any logging occurs
app.use(loggingMiddleware.requestHandler());

app.get('/', (req, res) => {
    res.send('Hello World!');
});

// This error middleware has should be run first
app.use(loggingMiddleware.errorHandler());

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

Express Middleware

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

This middleware populate the logger context with header attributes from the request, adds the context to the Elastic APM agent, and logs basic request/response information. The middleware should be used as early as possible.

Function Signature:

function expressMiddleware(options)

Available options are:

  • 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. 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.

Example:

app.use(monitoringMiddleware({requireRequestCorrelationId: false}));

Logging

Configuration

require('@abeai/logging').configure({appName: 'myAppName'});

Configuration Attributes:

  • appName: Is used to namespace log data which should be indexed. Is required.

Usage

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

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.

Example:

logger.info('log this');
logger.info('log with raw data', {unindexed: {aLotOfData: ...}});
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'));

Context Management

The context supports the following attributes:

  • 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.
  • cuiUserId: CUI User ID related to current request chain. This attribute is optional.

The current context can be managed with the following functions:

  • logger.setContext({channelType,channelId,channelIdentityId,agentId,userId,cuiUserId}): Overwites existing attributes.
  • logger.mergeContext({channelType,channelId,channelIdentityId,agentId,userId,cuiUserId}): Merges new attributes with existing attributes. New attributes win over existing attributes.
  • logger.context(): Returns all available context attributes as an object.

Context Propagation for Inter-Service Communication

The logger provides the function logger.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-User-ID

Example:

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

Log Output Structure

The structure is based on pino with some additions:

Normal Message

logger.info('log this');

Output:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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:

{
    "abeLogging": true,
    "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",
    "cuiUserId": "666e4567-e89b-12d3-a456-426655446666",
    "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>