diff --git a/.travis.yml b/.travis.yml index 398c814..8f8d410 100644 --- a/.travis.yml +++ b/.travis.yml @@ -2,3 +2,5 @@ language: node_js node_js: - "6" - "4.4" +script: + - npm run ci diff --git a/README.md b/README.md index 9d1bc26..090f13b 100644 --- a/README.md +++ b/README.md @@ -1,5 +1,11 @@ + + # olog -Opinionated Logging for Node.js - forces prescriptive, disciplined, structured logging. +[![Build Status](https://travis-ci.org/Nordstrom/olog-node.svg)](https://travis-ci.org/Nordstrom/olog-node) [![Coverage Status](https://coveralls.io/repos/github/Nordstrom/olog-node/badge.svg)](https://coveralls.io/github/Nordstrom/olog-node) [![Standard - JavaScript Style Guide](https://img.shields.io/badge/code%20style-standard-brightgreen.svg)](http://standardjs.com/) + + +Opinionated Logging for Node.js - forces prescriptive, disciplined, structured logging. This is logging based on predefined [Schemas] +(SCHEMAS.md) with default fields. Schema names, fields, and message formatting all have defaults but can all be configured. ## Install Install with: @@ -61,28 +67,37 @@ Outputs: ## API -* **[olog (options)](#olog-options)** +* **[record](#record)** +* **[olog (module\[, defaults\])](#olog-module-defaults)** * **[log.config (options)](#logconfig-options)** * **[log.debug (record)](#logdebug-record)** * **[log.info (record)](#loginfo-record)** * **[log.warn (record)](#logwarn-record)** * **[log.error (record)](*logerror-record)** -* **[log.serverDebug (record)](#logserverDebug-record)** -* **[log.serverInfo (record)](#logserverInfo-record)** -* **[log.serverWarn (record)](#logserverWarn-record)** -* **[log.serverError (record)](#logserverError-record)** -* **[log.clientDebug (record)](#logclientDebug-record)** -* **[log.clientInfo (record)](#logclientInfo-record)** -* **[log.clientWarn (record)](#logclientWarn-record)** -* **[log.clientError (record)](#logclientError-record)** -* **[log.httpApiStart (record)](#loghttpApiStart-record)** -* **[log.httpApiStop (record)](#loghttpApiStop-record)** -* **[log.httpUiStart (record)](#loghttpUiStart-record)** -* **[log.httpUiStop (record)](#loghttpUiStop-record)** -* **[log.httpApiSend (record)](#loghttpApiSend-record)** -* **[log.httpApiReceive (record)](#loghttpApiReceive-record)** -* **[log.eventStart (record)](#logeventStart-record)** -* **[log.eventStop (record)](#logeventStop-record)** +* **[log.serverDebug (record)](#logserverdebug-record)** +* **[log.serverInfo (record)](#logserverinfo-record)** +* **[log.serverWarn (record)](#logserverwarn-record)** +* **[log.serverError (record)](#logservererror-record)** +* **[log.clientDebug (record)](#logclientdebug-record)** +* **[log.clientInfo (record)](#logclientinfo-record)** +* **[log.clientWarn (record)](#logclientwarn-record)** +* **[log.clientError (record)](#logclienterror-record)** +* **[log.httpApiStart (record)](#loghttpapistart-record)** +* **[log.httpApiStop (record)](#loghttpapistop-record)** +* **[log.httpUiStart (record)](#loghttpuistart-record)** +* **[log.httpUiStop (record)](#loghttpuistop-record)** +* **[log.httpApiSend (record)](#loghttpapisend-record)** +* **[log.httpApiReceive (record)](#loghttpapireceive-record)** +* **[log.eventStart (record)](#logeventstart-record)** +* **[log.eventStop (record)](#logeventstop-record)** + +### record +Type: `Object` + +Log record used for all logging functions. This undergoes the following transformations during logging: +* Generates message field based on the messageFormatter for the given schema. +* Filters and orders fields based on configured fields for the schema (see [log.config (options)](#logconfig-options)). Only configured fields are output, and fields are output in the order they are configured. + ### olog (module[, defaults]) Factor function that creates a new logger. It makes it easy to require and create a logger for a module. @@ -101,17 +116,17 @@ Allows you to provide module-level defaults for any of the log record properties ```js // component name -const log = require('my-module') +const log = require('olog')('my-module') or // generates component name -const log = require(module) +const log = require('olog')(module) or // applies record defaults -const log = require(module, { +const log = require('olog')(module, { category: 'Shopping Cart', transaction: 'UpdateCart' }) @@ -125,62 +140,163 @@ Type: `Object` ##### options.application Type: `String` -Environment Variable: `OLOG_APPLICATION` + +Name or ID of the application. Set here or with Environment Variable `OLOG_APPLICATION`. ##### options.environment Type: `String` -Environment Variable: `OLOG_ENVIRONMENT` -##### options.level (process.env.OLOG_LEVEL) -Type: `String` +Name or ID of the deployed environment. Set here or with Environment Variable `OLOG_ENVIRONMENT`. + +##### options.level +Type: `String` one of `debug`, `info`, `warn`, `error` Default: `info` Environment Variable: `OLOG_LEVEL` +Name of log level enabled for this application. Set here or with Environment Variable `OLOG_LEVEL`. + ##### options.stream -Type: `Stream` +Type: `Stream` Default: process.stdout -##### options.messageTemplates -Type: `Object` +Writable stream to which log records are written. Records are output in UTF8 stringified JSON format. + +##### options.fields +Type: `Object` Default: +```js +{ + serverDebug: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions'] + serverInfo: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions'] + serverWarn: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions'] + serverError: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'exception'] + clientDebug: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'uri', 'userAgent', 'userAuth'] + clientInfo: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'uri', 'userAgent', 'userAuth'] + clientWarn: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'uri', 'userAgent', 'userAuth'] + clientError: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'uri', 'userAgent', 'userAuth', 'exception'] + httpApiStart: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'route', 'method', 'uri', 'requestHeaders', 'requestCookies', 'requestBodyString', 'requestBodyMap', 'requestBodyObject', 'referer', 'userAgent'] + httpApiStop: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'route', 'method', 'uri', 'requestHeaders', 'requestCookies', 'requestBodyString', 'requestBodyMap', 'requestBodyObject', 'referer', 'userAgent', 'duration', 'responseCode', 'responseHeaders', 'responseCookies', 'responseBodyString', 'responseBodyMap', 'responseBodyObject'] + httpUiStart: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'route', 'method', 'uri', 'requestHeaders', 'requestCookies', 'requestBodyString', 'requestBodyMap', 'requestBodyObject', 'referer', 'userAgent'] + httpUiStop: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'route', 'method', 'uri', 'requestHeaders', 'requestCookies', 'requestBodyString', 'requestBodyMap', 'requestBodyObject', 'referer', 'userAgent', 'duration', 'responseCode', 'responseHeaders', 'responseCookies', 'responseBodyString', 'responseBodyMap', 'responseBodyObject'] + httpApiSend: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'api', 'method', 'uri', 'requestHeaders', 'requestCookies', 'requestBodyString', 'requestBodyMap', 'requestBodyObject'] + httpApiReceive: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'api', 'method', 'uri', 'requestHeaders', 'requestCookies', 'requestBodyString', 'requestBodyMap', 'requestBodyObject', 'resonseCode', 'responseHeaders', 'responseCookies', 'responseBodyString', 'responseBodyMap', 'responseBodyObject', 'duration'], + eventStart: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'originatedAt', 'topic', 'partition', 'key', 'attributes'], + eventStop: ['time', 'message', 'level', 'schema', 'version', 'application', 'environment', 'host', 'pid', 'component', 'transaction', 'trace', 'annotations', 'extensions', 'originatedAt', 'topic', 'partition', 'key', 'attributes', 'duration', 'elapsed'] +} +``` +This determines allowed output fields for each schema along with the order of output for each field. + +##### options.schemaNames +Type: `Object` Default: +```js +{ + serverDebug: 'SERVER-Debug', + serverInfo: 'SERVER-Info', + serverWarn: 'SERVER-Warn', + serverError: 'SERVER-Error', + clientDebug: 'CLIENT-Debug', + clientInfo: 'CLIENT-Info', + clientWarn: 'CLIENT-Warn', + clientError: 'CLIENT-Error', + httpApiStart: 'HTTP-API-Start', + httpApiStop: 'HTTP-API-Stop', + httpUiStart: 'HTTP-UI-Start', + httpUiStop: 'HTTP-UI-Stop', + httpApiSend: 'HTTP-API-Send', + httpApiReceive: 'HTTP-API-Receive', + eventStart: 'EVENT-Start', + eventStop: 'EVENT-Stop' +} +``` + +Logged name of each schema based on function name. + +##### options.messageFormatters +Type: `Object` Default: +```js +{ + serverDebug: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + serverInfo: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + serverWarn: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + serverError: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}: ${r.exception}` }, + clientDebug: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + clientInfo: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + clientWarn: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + clientError: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}: ${r.exception}` }, + httpApiStart: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route} for ${r.trace}` }, + httpApiStop: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route}[${r.responseCode}] in ${r.duraton}ms for ${r.trace}` }, + httpUiStart: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route} for ${r.trace}` }, + httpUiStop: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route}[${r.responseCode}] in ${r.duraton}ms for ${r.trace}` }, + httpApiSend: (r) => { return `[${r.schema}] ${r.transaction}: ${r.api} (${r.method}:${r.uri}) for ${r.trace}` }, + httpApiReceive: (r) => { return `[${r.schema}] ${r.transaction}: ${r.api} (${r.method}:${r.uri})[${r.responseCode}] in ${r.duraton}ms for ${r.trace}` } +}, + +``` + +Configure message formatters for each schema. This Object contains properties following this syntax: +`: (record) => { return }`. +For example: + +```js +{ + serverInfo: (record) => { return `${record.transaction} - DETAILS: ${record.message}` }, + httpApiStop: (record) => { return `${record.route}[${record.responseCode}]` } +} +``` ### log.debug (record) -Alias for [log.serverDebug (record)](#logserverDebug-record). +Alias for [log.serverDebug (record)](#logserverdebug-record). ### log.info (record) -Alias for [log.serverInfo (record)](#logserverInfo-record). +Alias for [log.serverInfo (record)](#logserverinfo-record). ### log.warn (record) -Alias for [log.serverWarn (record)](#logserverWarn-record). +Alias for [log.serverWarn (record)](#logserverwarn-record). ### log.error (record) -Alias for [log.serverError (record)](#logserverError-record). +Alias for [log.serverError (record)](#logservererror-record). ### log.serverDebug (record) +Logs [record](#record) using serverDebug (SERVER-Debug) schema. ### log.serverInfo (record) +Logs [record](#record) using serverInfo (SERVER-Info) schema. ### log.serverWarn (record) +Logs [record](#record) using serverWarn (SERVER-Warn) schema. ### log.serverError (record) +Logs [record](#record) using serverError (SERVER-Error) schema. ### log.clientDebug (record) +Logs [record](#record) using clientDebug (CLIENT-Debug) schema. ### log.clientInfo (record) +Logs [record](#record) using clientInfo (CLIENT-Info) schema. ### log.clientWarn (record) +Logs [record](#record) using clientWarn (CLIENT-Warn) schema. ### log.clientError (record) +Logs [record](#record) using clientError (CLIENT-Error) schema. ### log.httpApiStart (record) +Logs [record](#record) using httpApiStart (HTTP-API-Start) schema. ### log.httpApiStop (record) +Logs [record](#record) using httpApiStop (HTTP-API-Stop) schema. ### log.httpUiStart (record) +Logs [record](#record) using httpUiStart (HTTP-UI-Start) schema. ### log.httpUiStop (record) +Logs [record](#record) using httpUiStop (HTTP-UI-Stop) schema. ### log.httpApiSend (record) +Logs [record](#record) using httpApiSend (HTTP-API-Send) schema. ### log.httpApiReceive (record) +Logs [record](#record) using httpApiReceive (HTTP-API-Receive) schema. ### log.eventStart (record) +Logs [record](#record) using eventStart (EVENT-Start) schema. ### log.eventStop (record) +Logs [record](#record) using eventStop (EVENT-Stop) schema. diff --git a/SCHEMAS.md b/SCHEMAS.md new file mode 100644 index 0000000..1ed9e04 --- /dev/null +++ b/SCHEMAS.md @@ -0,0 +1,91 @@ +# Logging Schemas +The following provides definitions of the Logging Schemas with defaults fields for each. + +## Core Fields +These fields are common to all Schemas. + +|Field|Type|Description| +|-----|----|-----------| +|**time**|Date|Generated date/time at which the log event was generated. The Timestamp should is expressed in UTC ISO 8601 format.| +|**message**|String|A summary message that contains other elements of data in the log (i.e. `HTTP-API-Stop on CreateProduct (POST:/v2/products) [200] in 138ms`). The purpose of this is to provide a condensed view of logs. Tools like Kibana, let you select the fields to show in the log view. Having a summary message allows a single line, condensed view rather than the whole record. This message is generated based on the messageFormatter for each schema.| +|**level**|String|Log level string (i.e. debug, info, warn, error). This is generated based on the schema function used.| +|**schema**|String|Case insensitive string identifier that identifies the schema of the log message.| +|**version**|Number|Integer-based version number that. Current: `3`| +|**application**|String|Unique string identifying the application generating the log events. This is set in the [log.config (options)](README.md#logconfig-options) or `OLOG_APPLICATION` environment variable.| +|**environment**|String|String field that is used as the name of the environment in which the application is currently executing. This is set in [log.config (options)](README.md#logconfig-options) or `OLOG_ENVIRONMENT` environment variable.| +|**host**|String|Name or id of host / server instance. This is automatically set by olog.| +|**pid**|String|ID of Process. This is automatically set by olog.| +|**component**|String|String field to record the module or component in which logging occurs. This is set based on the module param of [olog(module\[, defaults\])](README.md#olog-module-defaults).| +|**category**|String|String field that can be used to functionally categorize trace data (e.g. "Outfits-CacheMiss", "Outfits-CacheHit", ...).| +|**transaction**|String|Custom name for the type of transaction to which this log belongs. (e.g. CreateProduct, GetPrice, UpdateSkuDb, etc). This is helpful for correlating logs across a given type of transaction.| +|**trace**|String|Enables correlation of log data across applications for a specific request or transaction.| +|**extensions**|Object|Custom metadata as an Object type (JSON, Graph, etc).| + +## SERVER-Debug +**level:** `debug` + +Debug level logs that occur on the server. Core Fields only. + +## SERVER-Info +**level:** `info` + +Info level logs that occur on the server. Core Fields only. + +## SERVER-Warn +**level:** `warn` + +Warning level logs that occur on the server. Core Fields only. + +## SERVER-Error +**level:** `error` + +Error level logs that occur on the server. + +|Field|Type|Description| +|-----|----|-----------| +|**exception**|String|Field to record the exception that happened, along with the relevant stack trace.| + +## CLIENT-Debug +**level:** `debug` + +Debug level logs that occur on the client. + +|Field|Type|Description| +|-----|----|-----------| +|**uri**|String|Uri string.| +|**userAgent**|String|User agent string used to identify browser & device.| +|**userAuth**|String|Field to record the user auth state.| + +## CLIENT-Info +**level:** `info` + +Info level logs that occur on the client. + +|Field|Type|Description| +|-----|----|-----------| +|**uri**|String|Uri string.| +|**userAgent**|String|User agent string used to identify browser & device.| +|**userAuth**|String|Field to record the user auth state.| + +## CLIENT-Warn +**level:** `warn` + +Warning level logs that occur on the client. + +|Field|Type|Description| +|-----|----|-----------| +|**uri**|String|Uri string.| +|**userAgent**|String|User agent string used to identify browser & device.| +|**userAuth**|String|Field to record the user auth state.| + +## CLIENT-Error +**level:** `error` + +Error level logs that occur on the client. + +|Field|Type|Description| +|-----|----|-----------| +|**exception**|String|Records the exception that happened, along with the relevant stack trace.| +|**uri**|String|Uri string.| +|**userAgent**|String|User agent string used to identify browser & device.| +|**userAuth**|String|Field to record the user auth state.| diff --git a/cli.js b/cli.js new file mode 100644 index 0000000..4cfaa3a --- /dev/null +++ b/cli.js @@ -0,0 +1,5 @@ +'use strict' + +const log = require('./olog.js')(module) + +log.describeFields() diff --git a/olog.js b/olog.js new file mode 100644 index 0000000..b71b8b5 --- /dev/null +++ b/olog.js @@ -0,0 +1,281 @@ +'use strict' + +const os = require('os') +const stringify = require('fast-safe-stringify') + +const debug = 0 +const info = 1 +const warn = 2 +const error = 3 + +const levelNum = { + debug: debug, + info: info, + warn: warn, + error: error +} + +// logging schema version +const version = 3 + +const coreFields = [ + 'time', + 'message', + 'level', + 'schema', + 'version', + 'application', + 'environment', + 'host', + 'pid', + 'component', + 'category', + 'transaction', + 'trace', + 'annotations', + 'extensions' +] + +const clientFields = [ + 'uri', + 'userAgent', + 'userAuth' +] + +const httpStartFields = [ + 'route', + 'method', + 'uri', + 'requestHeaders', + 'requestCookies', + 'requestBodyString', + 'requestBodyMap', + 'requestBodyObject', + 'referer', + 'userAgent' +] + +const httpStopFields = httpStartFields.concat([ + 'duration', + 'responseCode', + 'responseHeaders', + 'responseCookies', + 'responseBodyString', + 'responseBodyMap', + 'responseBodyObject' +]) + +const httpSendFields = [ + 'api', + 'method', + 'uri', + 'requestHeaders', + 'requestCookies', + 'requestBodyString', + 'requestBodyMap', + 'requestBodyObject' +] + +const httpReceiveFields = httpSendFields.concat([ + 'resonseCode', + 'responseHeaders', + 'responseCookies', + 'responseBodyString', + 'responseBodyMap', + 'responseBodyObject', + 'duration' +]) + +const eventStartFields = [ + 'originatedAt', + 'topic', + 'partition', + 'key', + 'attributes' +] + +const eventStopFields = eventStartFields.concat([ + 'duration', + 'elapsed' +]) + +let appOpts = { + level: process.env.OLOG_LEVEL || 'info', + application: process.env.OLOG_APPLICATION, + environment: process.env.OLOG_ENVIRONMENT, + pid: stringify(process.pid), + host: os.hostname(), + version: version, + stream: process.stdout, + schemaNames: { + serverDebug: 'SERVER-Debug', + serverInfo: 'SERVER-Info', + serverWarn: 'SERVER-Warn', + serverError: 'SERVER-Error', + clientDebug: 'CLIENT-Debug', + clientInfo: 'CLIENT-Info', + clientWarn: 'CLIENT-Warn', + clientError: 'CLIENT-Error', + httpApiStart: 'HTTP-API-Start', + httpApiStop: 'HTTP-API-Stop', + httpUiStart: 'HTTP-UI-Start', + httpUiStop: 'HTTP-UI-Stop', + httpApiSend: 'HTTP-API-Send', + httpApiReceive: 'HTTP-API-Receive', + eventStart: 'EVENT-Start', + eventStop: 'EVENT-Stop' + }, + messageFormatters: { + serverDebug: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + serverInfo: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + serverWarn: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + serverError: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}: ${r.exception}` }, + clientDebug: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + clientInfo: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + clientWarn: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}` }, + clientError: (r) => { return `[${r.schema}] ${r.transaction}: ${r.message}: ${r.exception}` }, + httpApiStart: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route} for ${r.trace}` }, + httpApiStop: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route}[${r.responseCode}] in ${r.duraton}ms for ${r.trace}` }, + httpUiStart: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route} for ${r.trace}` }, + httpUiStop: (r) => { return `[${r.schema}] ${r.transaction}: ${r.route}[${r.responseCode}] in ${r.duraton}ms for ${r.trace}` }, + httpApiSend: (r) => { return `[${r.schema}] ${r.transaction}: ${r.api} (${r.method}:${r.uri}) for ${r.trace}` }, + httpApiReceive: (r) => { return `[${r.schema}] ${r.transaction}: ${r.api} (${r.method}:${r.uri})[${r.responseCode}] in ${r.duraton}ms for ${r.trace}` } + }, + fields: { + serverDebug: coreFields.concat([]), + serverInfo: coreFields.concat([]), + serverWarn: coreFields.concat([]), + serverError: coreFields.concat(['exception']), + clientDebug: coreFields.concat(clientFields), + clientInfo: coreFields.concat(clientFields), + clientWarn: coreFields.concat(clientFields), + clientError: coreFields.concat(clientFields.concat(['exception'])), + httpApiStart: coreFields.concat(httpStartFields), + httpApiStop: coreFields.concat(httpStopFields), + httpUiStart: coreFields.concat(httpStartFields), + httpUiStop: coreFields.concat(httpStopFields), + httpApiSend: coreFields.concat(httpSendFields), + httpApiReceive: coreFields.concat(httpReceiveFields), + eventStart: coreFields.concat(eventStartFields), + eventStop: coreFields.concat(eventStopFields) + } +} + +let compOpts = {} + +class Log { + constructor (component, defaults) { + this.component = component + this.defaults = defaults || {} + } + + static config (options) { + appOpts = Object.assign(appOpts, options) + } + + describeFields () { + for (var id in appOpts.fields) { + let fields = appOpts.fields[id].map((field) => { return `'${field}'` }).join(', ') + console.log(`${id}: [${fields}]`) + } + // console.log(JSON.stringify(appOpts.fields, null, 2)) + // console.log(appOpts) + } + + _normalize (id, record) { + const self = this + const fields = (compOpts.fields && compOpts.fields[id]) || appOpts.fields[id] + + if (!fields || !(fields.length > 0)) return {} + + let normalized = {} + + for (let i = 0; i < fields.length; i++) { + let field = fields[i] + let value = record[field] || self.defaults[field] || compOpts[field] || appOpts[field] + + if (value !== undefined && value !== null) { + normalized[field] = value + } + } + + return normalized + } + + _levelNotEnabled (level) { + // check that level num is less than the default level + // return true if so; false otherwise + return (level < levelNum[appOpts.level]) + } + + _formatMessage (id, record) { + // use id to lookup message formatter, passing record in to the formatter fn + // return formatted message + return appOpts.messageFormatters[id](record) + } + + _write (id, level, record) { + record.component = this.component + record.time = (new Date()).toISOString() + record.level = level + // 1. get schemaName by id + record.schema = appOpts.schemaNames[id] + // 2. format message + record.message = this._formatMessage(id, record) + // 3. normalize record + record = this._normalize(id, record) + // 4. write record to stream + appOpts.stream.write(stringify(record)) + } + + // Server logging functions + // todo: these can all be dynamically generated w/ ES6 + serverDebug (record) { + if (this._levelNotEnabled(debug)) return + this._write('serverDebug', 'debug', record) + } + debug () { this.serverDebug.apply(this, arguments) } + + serverInfo (record) { + if (this._levelNotEnabled(info)) return + this._write('serverInfo', 'info', record) + } + info () { this.serverInfo.apply(this, arguments) } + + serverWarn (record) { + if (this._levelNotEnabled(warn)) return + this._write('serverWarn', 'warn', record) + } + warn () { this.serverWarn.apply(this, arguments) } + + serverError (record) { + this._write('serverError', 'error', record) + } + error () { this.serverError.apply(this, arguments) } + + // Client logging functions + clientDebug (record) { + if (this._levelNotEnabled(debug)) return + this._write('clientDebug', 'debug', record) + } + + clientInfo (record) { + if (this._levelNotEnabled(info)) return + this._write('clientInfo', 'info', record) + } + + clientWarn (record) { + if (this._levelNotEnabled(warn)) return + this._write('clientWarn', 'warn', record) + } + + clientError (record) { + this._write('clientError', 'error', record) + } +} + +module.exports = (component, defaults) => { + return new Log(component, defaults) +} + +module.exports.Log = Log diff --git a/package.json b/package.json index 59a15f5..c9a5539 100644 --- a/package.json +++ b/package.json @@ -1,12 +1,13 @@ { "name": "olog", - "version": "0.1.0", + "version": "0.2.0", "description": "Opinionated Logging for Node.js - forces prescriptive, disciplined, structured logging", - "main": "index.js", + "main": "olog.js", "scripts": { - "test": "standard && istanbul test _mocha", - "lint": "standard", - "tdd": "mocha -w" + "test": "snazzy && istanbul cover _mocha", + "lint": "snazzy", + "tdd": "mocha -w", + "ci": "snazzy && istanbul cover _mocha --report lcovonly -- -R spec && cat ./coverage/lcov.info | ./node_modules/coveralls/bin/coveralls.js" }, "repository": { "type": "git", @@ -30,9 +31,15 @@ }, "homepage": "https://github.com/Nordstrom/olog-node#readme", "devDependencies": { + "coveralls": "^2.11.15", "istanbul": "^0.4.5", "mocha": "^3.1.2", + "mocha-lcov-reporter": "^1.2.0", "should": "^11.1.1", + "snazzy": "^5.0.0", "standard": "^8.5.0" + }, + "dependencies": { + "fast-safe-stringify": "^1.1.3" } } diff --git a/test/index.js b/test/index.js new file mode 100644 index 0000000..bed30d1 --- /dev/null +++ b/test/index.js @@ -0,0 +1,233 @@ +'use strict' +var should = require('should') +var describe = require('mocha').describe +var it = require('mocha').it +var beforeEach = require('mocha').beforeEach +var olog = require('../olog') +var catcher = require('./util/logCatcher') + +const ISO_REGEX = /\d{4}-[01]\d-[0-3]\dT[0-2]\d:[0-5]\d:[0-5]\d\.\d+([+-][0-2]\d:[0-5]\d|Z)/ +const HOSTNAME_REGEX = /^(?=.{1,255}$)[0-9A-Za-z](?:(?:[0-9A-Za-z]|-){0,61}[0-9A-Za-z])?(?:\.[0-9A-Za-z](?:(?:[0-9A-Za-z]|-){0,61}[0-9A-Za-z])?)*\.?$/ +const PID_REGEX = /[0-9]*/ + +// setup the catcher as the stream for logs +function resetTestLogger () { + catcher.clear() + olog.Log.config({stream: catcher}) +} + +describe('basic logging functionality', () => { + beforeEach(resetTestLogger) + + it('should log basic message', () => { + let log = olog('componentName') + log.serverInfo({transaction: 'CreateComponent', message: 'Encountered issue creating component'}) + + should(catcher.getParsedRecord(0)).have.property('transaction', 'CreateComponent') + catcher.getParsedRecord(0).message.should.equal('[SERVER-Info] CreateComponent: Encountered issue creating component') + }) + + describe('using the readme example', () => { + let productId = '123' + var expectedLog, logInput, log + beforeEach(() => { + logInput = { + message: `Db Update on Product ${productId}`, + category: 'Catalog', + transaction: 'CreateProduct', + trace: 'e45dc587-3516-489f-9487-391a119889c0', + annotations: { + productId: productId + } + } + expectedLog = { + 'time': ISO_REGEX, + 'message': '[SERVER-Info] CreateProduct: Db Update on Product 123', + 'level': 'info', + 'schema': 'SERVER-Info', + 'version': 3, + 'host': HOSTNAME_REGEX, + 'pid': PID_REGEX, + 'component': 'lib/mymodule', + 'category': 'Catalog', + 'transaction': 'CreateProduct', + 'trace': 'e45dc587-3516-489f-9487-391a119889c0', + 'annotations': { + 'productId': '123' + } + } + log = olog('lib/mymodule') + log.serverInfo(logInput) + }) + it('should output the same log as stated in the readme', function () { + catcher.getParsedRecord(0).should.match(expectedLog) + }) + it('should have fields in the correct order', () => { + Object.keys(catcher.getParsedRecord(0)).should.eql(Object.keys(expectedLog)) + }) + }) + + describe('default options', () => { + it('should use defaults in all generated logs', () => { + let defaults = { + category: 'Shopping Cart', + transaction: 'UpdateCart' + } + olog('defaultTest', defaults) + .serverInfo({message: 'Default options should be used'}) + + catcher.getParsedRecord(0).should.have.property('component', 'defaultTest') + catcher.getParsedRecord(0).should.match(defaults) + }) + + it('should override app options with default options', () => { + olog('defaultOverrideTest', { version: 2 }) + .serverInfo({message: 'Should override version'}) + + catcher.getParsedRecord(0).should.match({ + 'version': 2, + 'component': 'defaultOverrideTest' + }) + }) + + it('should override defaults with log record properties', () => { + const log = olog('recordDefaultTest', { + category: 'Shopping Cart', + transaction: 'UpdateCart' + }) + log.serverInfo({message: 'Default options should be used', transaction: 'ClearCart'}) + + catcher.getParsedRecord(0).should.have.property('category', 'Shopping Cart') + catcher.getParsedRecord(0).should.have.property('transaction', 'ClearCart') + }) + + it('should not modify app options of other logs', () => { + olog('defaultOverrideTest', { version: 2 }) + .serverInfo({message: 'Should override version'}) + + catcher.getParsedRecord(0).should.match({ + 'version': 2, + 'component': 'defaultOverrideTest' + }) + + olog('notModifiedTest', {transaction: 'UpdateCart'}) + .serverInfo({message: 'Should not override version'}) + + catcher.getParsedRecord(1).should.match({ + 'version': 3, + 'component': 'notModifiedTest' + }) + }) + }) + + describe('config function', () => { + it('should change app options for current loggers', () => { + const log = olog('componentName') + log.serverInfo({message: 'Should not have an application field'}) + catcher.getParsedRecord(0).should.not.have.property('application') + + olog.Log.config({application: 'UnitTests'}) + + log.serverInfo({message: 'Should have an application field'}) + catcher.getParsedRecord(1).should.have.property('application', 'UnitTests') + }) + + it('should change app options for all loggers', () => { + olog.Log.config({application: 'UnitTests'}) + + olog('component2Name') + .serverInfo({message: 'Should have an application field'}) + catcher.getParsedRecord(0).should.have.property('application', 'UnitTests') + }) + }) + describe('logging level', () => { + describe('should not write logs lower than set level', () => { + it('when using the default level \'info\'', () => { + olog('debugIgnoreTest') + .serverDebug({message: 'Should not be written to stream'}) + catcher.records.length.should.eql(0) + }) + it('when manually configured to have level \'error\'', () => { + let log = olog('allIgnoreTest') + olog.Log.config({ level: 'error' }) + log.serverDebug({message: 'Should be ignored'}) + log.serverInfo({message: 'Should be ignored'}) + log.serverWarn({message: 'Should be ignored'}) + catcher.records.length.should.eql(0) + }) + }) + describe('server logging functions should have shorter aliases', () => { + it('debug', () => { + let log = olog('debugAliasTest') + olog.Log.config({ level: 'debug' }) + log.debug({message: 'Should have debug level'}) + catcher.getParsedRecord(0).should.have.property('level', 'debug') + }) + it('info', () => { + olog('infoAliasTest') + .info({message: 'Should have info level'}) + catcher.getParsedRecord(0).should.have.property('level', 'info') + }) + it('warn', () => { + olog('warnAliasTest') + .warn({message: 'Should have warn level'}) + catcher.getParsedRecord(0).should.have.property('level', 'warn') + }) + it('error', () => { + olog('errorAliasTest') + .error({message: 'Should have error level'}) + catcher.getParsedRecord(0).should.have.property('level', 'error') + }) + }) + }) +}) + +describe('client logging schema', () => { + let productId = '123' + var testRecord = { + 'message': `Price check on Product ${productId}`, + 'url': 'https://store.nordstrom.com/products/123/pricing', + 'userAgent': 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.71 Safari/537.36', + 'userAuth': 'hash:29283lsadf,name:andy', + 'transaction': 'LoadProductPrice', + 'trace': 'e45dc587-3516-489f-9487-391a119889c0', + 'annotations': { + 'productId': productId + } + } + beforeEach(resetTestLogger) + describe('should have a client logger function defined for all levels', () => { + it('clientDebug', () => { + let log = olog('ProductService.PriceAdapter.LoadPrice') + olog.Log.config({ level: 'debug' }) + log.clientDebug(testRecord) + catcher.getParsedRecord(0).should.have.property('level', 'debug') + }) + it('clientInfo', () => { + olog('ProductService.PriceAdapter.LoadPrice') + .clientInfo(testRecord) + catcher.getParsedRecord(0).should.have.property('level', 'info') + }) + it('clientWarn', () => { + olog('ProductService.PriceAdapter.LoadPrice') + .clientWarn(testRecord) + catcher.getParsedRecord(0).should.have.property('level', 'warn') + }) + it('clientError', () => { + var clientException = new Error('Error rendering price section') + var errorRecord = Object.assign({}, {'exception': clientException.stack}, testRecord) + olog('ProductService.PriceAdapter.LoadPrice') + .clientError(errorRecord) + catcher.getParsedRecord(0).should.have.property('level', 'error') + }) + }) + it('ignores logs below current level', () => { + // set level to error + let log = olog('ProductService.PriceAdapter.LoadPrice') + olog.Log.config({ level: 'error' }) + log.clientDebug(testRecord) + log.clientInfo(testRecord) + log.clientWarn(testRecord) + catcher.records.length.should.eql(0) + }) +}) diff --git a/test/util/logCatcher.js b/test/util/logCatcher.js new file mode 100644 index 0000000..0eed91f --- /dev/null +++ b/test/util/logCatcher.js @@ -0,0 +1,22 @@ +var Catcher = function () { + this.records = [] +} +Catcher.prototype.write = function (record) { + this.records.push(record) +} +Catcher.prototype.clear = function () { + this.records = [] +} +Catcher.prototype.getParsedRecord = function (index) { + var record = this.records[index] + if (!record) return {} + var parsed + try { + parsed = JSON.parse(record) + } catch (err) { + parsed = record + } + return parsed +} + +module.exports = new Catcher()