About this Notebook
This notebook demonstrates the npm package @goodware/log. Clone and modify it to explore the package's functionality. Kick the tires right here on RunKit!
- npm: https://www.npmjs.com/package/@goodware/log
- git: https://github.com/good-ware/js-log
- API Docs: https://good-ware.github.io/js-log/
- Release History: https://good-ware.github.io/js-log/tutorial-CHANGELOG
- Support: https://github.com/good-ware/js-log/issues
Introduction
Are your Winston3 logs missing stack traces? Are you looking for an out of the box solution that works with some of the most popular Winston3 transports or for advanced Winston3 sample code? Have you noticed that your AWS Lambda functions can't send messages reliably CloudWatch Logs log groups?
@goodware/log is a great place to start. It logs stack traces and converts complex data (even with circular references) to JSON. It can send logs to AWS CloudWatch Logs and can wait for queued messages to be flushed, which is an unfortunate requirement for AWS Lambda functions that send messages to abitrary log groups, but is generally useful for other use cases.
@goodware/log extends Winston3 with features such as tag-based filtering and is intended for Node-like environments instead of web browsers. It can log scalars, objects (including those with cyclical references), arrays, and graphs of Error instances (with stack traces) quickly and reliably.
Log entries can be sent to any combination of the following transports: console (via winston-console-format), files (via winston-daily-rotate-file) in JSON format, and, optionally, CloudWatch Logs (via winston-cloudwatch). All messages are logged in JSON format.
@goodware/log features a large unit test suite and has been servicing a commercial SaaS product for several years. It is BSD licensed.
Support
Post questions, suggestions, bug reports, and feature requests to https://github.com/good-ware/js-log/issues.
Requirements
As of @goodware/log version 9, NodeJS version 14+ is required. Versions 8 and earlier work with NodeJS 8 and later. When the CloudWatch Logs transport is used, NodeJS support depends upon that of @aws-sdk.
Housekeeping
The capture-console package is needed by this notebook to display console output. Also, many code cells end with 'null;' to avoid cluttering the notebook. (This library is awesome. I should have used it for unit testing.)
const capcon = require("capture-console"); null;
Configuration
This example creates a Loggers instance that sends log entries to the console. The configuration object that is sent to the constructor of the Loggers class is defined by a Joi schema located at https://tinyurl.com/yv3h3sup.
const Loggers = require('@goodware/log');
const options = {
stage: process.env.NODE_ENV, // This is the value for the 'stage' property that appears in all
// log entries (aka meta property)
service: 'Example', // The name of this program (another meta property)
version: '1.0.0', // The program's version (another meta property)
commitSha: 'RunKit Example (no git repo)',
console: {
colors: true, // Create visually appealing console entries with ANSI colors. The color of each
// logging level can be specified. true is the default.
data: true, // Send all logged data (including stack traces) to the console, not just the message
},
cloudWatch: {
// This is provided as an example only. In order to log to CloudWatch Logs, your environment
// must be configured to use the AWS SDK.
region: 'us-west-2', // This is optional. The following environment variables will be
// used, if set, in the following order:
// AWS_CLOUDWATCH_LOGS_REGION; AWS_REGION
logGroup: `/${process.env.NODE_ENV}/goodware/log`,
},
categories: {
// These are named loggers aka Winston categories. Each category can specify which transports
// to use: console, file, or cloudWatch, and at which logging level. All categories inherit
// from the default category. Logging levels are configurable. By default they are:
// fail, error, warn, notice, info, more, db, http, verbose, debug, silly
default: {
console: 'silly',
cloudWatch: 'off',
file: 'off',
errorFile: 'off',
},
briefConsole: {
console: {
level: 'info',
data: false,
},
},
},
};
// loggers is shared with other code cells
let loggers;
capcon.captureStdout(() => {
loggers = new Loggers(options);
});
The above message can be disabled. It is sent to the console when creating a new Loggers instance because:
1. 'say' configuration defaults to { ready: true }
2. The default logging level (debug) is used
3. The default logging level filter for the console is 'silly'
Meta Properties
Meta properties are the top-level properties of log entries. The default meta properties are:
- timestamp
- ms (elpased time between log entries in milliseconds)
- tags (array)
- level
- message
- category
- id
- groupId
- depth (>= 2)
- hostId
- stage
- service (the name of your service)
- version (the version of your service)
- stack
- logStack (call stack when 'level' is 'error')
- transports (array of Winston transport names)
Additional meta properties can be specified via the metaProperties options setting.
Category
Following Winston's terminology, a 'category' is the name of a logger object. This library has two logger classes: Loggers and Logger. They mostly share the same interface. One Loggers instance manages a collection of named Logger instances.
Message
The message of a log entry is the star of the show. Messages are usually strings but any type is allowed except for functions.
Data
Additional data passed to logging methods (strings, objects, arrays, etc.) is located in log entries in the 'data' property. Data values are usually objects but any type is allowed except for functions. Error objects are handled specially in order to log nested errors.
Context
Context is just data with a different name and is typically associated with child loggers. Context values are usually objects but any type is allowed except for functions.
Child Loggers
Child loggers (instances of the class Logger) make it easy to log the same tags and context without repetitive code. Set it and forget it!
Logger Stacks (not call stacks)
Sometimes it's handy to set a child logger's tags or context temporarily inside a block scope. Logger objects can be pushed onto and popped from Stack instances. Like categories, stack objects must be uniquely named.
Quieter Console
The above output is certainly a lot of information to digest! The above output is sent to the console only when 'console data mode' is enabled. See the 'console' property in the configuration object above.
Sending noisy raw data to the console is appropriate for development. During runtime, verbose output is more appropriate for files and CloudWatch Logs. When 'console.data' is falsey, only brief messages appear in the console:
let briefConsole; // This is used by other code cells
{
const optionsCopy = JSON.parse(JSON.stringify(options));
optionsCopy.console.data = false;
briefConsole = new Loggers(optionsCopy);
}
capcon.captureStdout(() => {
briefConsole.log(['info','warn'],'A brief word');
});
+1ms represents the amount of time since the Loggers instance last logged a message (excluding the messages that are filtered out).
Unique log entry ids are shown in the console (after the message, in brackets) to facilitate searching files and CloudWatch Logs which will likely contain more information. You might appreciate these ugly ids when you need them.
Console settings can be specified on a per-category basis. The root 'console' property establishes default console settings so they must be overridden.
capcon.captureStdout(() => {
loggers.logger('briefConsole').info('Another brief word')
});
Loggers Instances
By now you're probably asking: "Why create a Loggers instance? Why isn't it a singleton? Doesn't this make the library harder to use?"
Unlike Winston, this library doesn't use global variables. Therefore, Loggers instances can not interfere with each other. Multiple third-party applications can use this library safely in the same process without, for example, clashing over category names.
Logger Interface
Loggers and Logger (returned by logger() and child()) objects support the following interface (https://good-ware.github.io/js-log/Loggers.html):
- start()
- async stop()
- async restart()
- ready (property)
- log(...)
- default() The default level is specified via option
- <level>(), where level is a logging level name. For example: info()
- child()
- stack()
- context()
- logger(category [, logger])
- parent (property). For child loggers to access their parent, which is either a Loggers object or a child logger
- loggers (property). For child loggers to access the Loggers object that created them
- winstonLogger(category)
- tags(...), for combining tags
- category() (mostly useful for retrieving the category assigned to logger objects)
- async flush()
- async flushCloudWatchTransports()
Logging Levels
Messages are filtered based on logging levels. For example, 'info' messages will not be sent to a transport that is configured to use the 'warn' level. Levels also affect colorization.
A logging levels are associated with severity values which are usually integers. The lower the value, the higher the severity. Thus, for example, 'error' has a severity of 3 whereas 'warn' has a severity of 3.
Logging levels and their corresponding severities and colors are configurable.
The default levels, in order of severity, are:
- fail
- *error
- *warn
- notice
- info
- more
- db
- http
- verbose
- *debug
- silly
The levels marked with * must exist.
Logging-level Methods
Methods named after logging levels, such as error(), exist for readability and convenience.
Since logging levels are configurable, the methods of logger objects vary depending on how they are configured. log(), error(), warn(), debug(), and default() are always available.
Configuring the set of levels is dangerous because can impact users of the library in unexpected ways. Choose new level names that aren't likely to clash with existing method or tag names. The library's maintainers take care when adding methods to the Loggers class.
Determining the Logging Level
A log entry has one logging level. The level is determined via 'tags' that are either sent to methods explicitly or implicitly via child loggers. log() chooses the most severe level when given an array of tags:
capcon.captureStdout(()=>{
loggers.logger('briefConsole').log(['info', 'warn'], 'Danger Will Robinson');
});
However, <level>() methods use the method name as the level:
capcon.captureStdout(()=>{
loggers.logger('briefConsole').info(['warn'], 'Danger Will Robinson')
});
Notice that 'info' appears before 'warn' in the tags list. The log entry's level always appears first.
Tags can even be removed by passing an object of tags. This is only needed when using child loggers.
capcon.captureStdout(()=>{
loggers.logger('briefConsole').child('warn').log( {warn: 0, info: true }, 'This is a silly example')
});
Logging Errors
This library logs errors and other objects without requiring any additional code. Stack traces are sent to files, CloudWatch Logs, and to the console when data is enabled.
The following example generates two log entries, one for 'Message' and one for 'Inner Error'. The log entries are related via the 'groupId' meta property:
capcon.captureStdout(() => {
loggers.error('Message', new Error('Inner error'));
});
Or, if you prefer the readability of named parameters:
capcon.captureStdout(() => {
loggers.error({message: 'Message', error: new Error('Inner Error')});
});
An Error object can be passed as message, data, or context. When an Error instance is passed as the first parameter to log(), the 'error' tag is added.
capcon.captureStdout(() => {
loggers.log(new Error('Something went wrong'));
});
logStack
When the logging level is 'error' or another tag specified via the logStackLevels option, the stack trace of the caller is also logged and appears in the 'logStack' meta property (see above). It can be disabled via the logStack meta tag:
capcon.captureStdout(() => {
loggers.log({error: true, logStack: false}, new Error('Something went wrong'));
});
In the above output, logStack is omitted from the meta properties.
Call stacks are not sent to console transports that are configured with a falsey value for the data option.
capcon.captureStdout(() => {
briefConsole.log('error', 'A message', {error: new Error('Something went wrong')});
});
Categories and Loggers
A Loggers instance is a logger object whose name is specified via the 'defaultCategory' options setting. It defaults to 'general.' The 'defaultCategory' options setting is used whenever a category is not specified.
Logger instances inherit the settings of the 'default' category (not the 'defaultCategory' options setting).
A category can be specified when calling logger(), child(), log(), default(), <level>(), and isLevelEnabled().
const threadLogger = loggers.logger('threads');
capcon.captureStdout(() => {
threadLogger.info('Started a thread');
});
Overloads
Most methods are overloaded to accept the following parameter groups:
(1) One to five parameters: (tags, message, data, context, category)
All arguments can be null or undefined.
- tags: string, array, or object. To specify additional tags to the <level>() methods, this argument must be an array.
- message: any. For example, an Error object may be provided. Does not apply to child() and isLevelEnabled().
- data: any
- category: string
If tags, message, data, or context are Error objects, the 'error' tag is added automatically. The same occurs when message or data are objects with an error property. Does not apply to child() and isLevelEnabled().
If message or data are objects, their 'error' properties are inspected for errors. Does not apply to child() and isLevelEnabled().
(2) One parameter: An object with at least one of the properties: {tags, context, message, error, data, category}. The properties of the provided object are identical to the positional properties described above.
(3) Two parameters, for use with a HAPI plugin
- tags: string, array, or object. To specify additional tags to the <level>() methods, this argument must be an array.
- An object with at least one of the properties: {tags, context, message, error, data, category}
capcon.captureStdout(() => {
loggers.log('info', 'A message', { a: 'Some data' } );
});
// <level>() methods require tags to be specified in an array
capcon.captureStdout(() => {
loggers.info(['sql'], { message: 'A message', error: new Error('An Error') });
});
In the above output, notice how the level is 'info' but the 'error' tag was added because an 'error' property exists in the second argument. When filtering messages with third party tools, it is common to use the 'level' meta property instead of the 'tags' array.
capcon.captureStdout(() => {
loggers.info(['sql'], { message: 'A message', data: { a: 'Some data' }, category: 'fruit' });
});
Tags
Tags are arbitrary strings that may or may not correspond to logging levels. Tags can be used for advanced filtering (see the next section).
Tags are also useful for log analysis, which is beyond the scope of this guide. For example, you might want to search files, console output, or CloudWatch Log for a particular tag.
capcon.captureStdout(() => {
loggers.log(['sql', 'thread'], new Error('Inner error'));
});
Notice the error tag was added automatically. Let's call that method again with an object so it's more readable:
capcon.captureStdout(() => {
loggers.warn({tags: ['sql', 'thread'], error: new Error('Inner error')});
});
In the above example, 'error' was added as a tag but the log entry's level is 'warn' because warn() was called.
Meta Tags
Meta tags alter the behavior of the logger. The meta tags are:
logStack: If this meta tag has a falsy value, the caller's stack will not be logged when the logging level is 'error' (or another tag specified via the logStackLevels option). When truthy, the caller's stack will be logged.
capcon.captureStdout(() => {
loggers.debug(['logStack'], `I'm adding a stack trace`);
});
Notice that in the example above, when an array is passed as the first argument to <level>() methods, the array is treated as 'tags.'
Tag Filtering
In addition to filtering based on logging levels (which are a subset of tags), categories and even specific transports within categories can be configured to filter message based on tags. Therefore, it is not necessary to add new logging levels (which affects <level>() methods) for fine-grained filtering.
Logging levels do not participate in tag filtering. The 'default' category specifies the default behavior for categories that do not appear in the configuration object.
Tags are enabled and disabled on a per-category basis. All tags are enabled by default. When the log entry's severity level is 'warn' or higher, tags are enabled by default; however, this behavior can be overidden via the 'allowLevel' setting.
Tags can be enabled either via the literal 'on' or via an object that has, among others, a 'level' property. When a level is specified, the log entry's severity level is changed accordingly.
Let's consider the following use case:
SQL statements are logged with the 'db' level. SQL statements should be logged only during development and troubleshooting. Therefore, the tag 'sql' is normally disabled. The 'sql' tag is enabled manually or via, say, an environment variable. Here we add two additional categories to simplify the example. In "real" scenarios, only one category would be used but its configuration would vary.
The following configuration enables the tag 'sql' for only two categories: one and two. Category 'one' changes the level to 'more' and sends log entries only to the file and console transports. Category 'two' sends log entries to all transports.
{
const optionsCopy = JSON.parse(JSON.stringify(options));
optionsCopy.categories = {
default: {
console: 'db',
tags: {
sql: 'off', // Disable for all transports for all categories. Log entries with warn and error
// levels are logged.
},
},
one: {
tags: {
sql: {
// Fine-tune filtering for category 'one.' All of these properties are optional.
allowLevel: 'off', // Enable tag filtering for all log entries regardless of their levels. 'off' is needed
// because the default is 'warn.'
level: 'db', // Set the log entry's level to 'more'
// Log entries are sent to all transports by default (console, file, errorFile, cloudWatch). Each transport
// can be overridden:
file: 'verbose', // Send a log entry with the 'sql' tag to the file transport if the log entry's severity
// level is equal to or greater than 'verbose'
console: 'on', // Send a log entry with the 'sql' tag to the console transport
other: 'off', // Do not send a log entry with the 'sql' tag to CloudWatch
},
},
},
two: {
tags: {
sql: 'on', // Send all log entries with the 'sql' tag to all transports for category two
},
},
};
const loggers2 = new Loggers(optionsCopy);
capcon.captureStdout(() => {
loggers2.silly('This is not logged'); // This is not logged because the console's level is 'db'
loggers2.db(['sql'], 'This is not logged'); // This is not logged because the sql tag is disabled by default
loggers2.db('Logging to general (level = db)'); // This is logged because the sql tag is not specified
loggers2.logger('one').silly(['sql'], 'Logging SQL to one (level = db)'); // sql is enabled via {level: 'db'}
loggers2.logger('two').info(['sql'], 'Logging SQL to two (level = info)'); // sql is enabled via 'on'
});
}
Although 'message' can be an object, 'data' and 'context' can also be used to log additional information. This allows 'message' to be a string or other scalar value.
capcon.captureStdout(() => {
loggers.error('Operation failed', {error: new Error('An error'), counter: 5});
});
Notice that the provided Error object (in deata) is logged separately, in case it has nested errors.
When message is an object and it has the same properties that exist in data, data and message are logged separately to avoid data loss.
capcon.captureStdout(() => {
loggers.info({a: 5}, {a: 10});
});
The above outputs two log entries because message and data both have 'a' properties with different values.
Child Loggers
Logger instances are created via logger() and child(). They have their own read-only tags, context, and category properties that are accessed via methods of the same names. Specify tags and data with child().
Log context can be built up by chaining calls to logger() and/or child(). Properties having the same name as properties in parent loggers are overwritten.
capcon.captureStdout(() => {
const child1 = loggers.child(['tag1'], { operationId: 1, requestId: 'AEF1X' });
child1.info('First child');
const child2 = child1.child(null, { operationId: 2 });
child2.warn('Second child');
});
capcon.captureStdout(() => {
loggers.logger('dog').child('dogTag').child(null, { userId: 101 }).logger('poodle')
.debug('Woof!');
});
Named Logger Stacks
Log context can be accumulated in stack structures. Stack (https://good-ware.github.io/js-log/Stack.html) instances store values of any data type in a stack data structure. Stack instances are looked up by their names which are arbitrary strings.
capcon.captureStdout(() => {
const stack = loggers.stack(); // Use the default name
stack.push(loggers.child('tag1'));
stack.push(stack.top().child('tag2'));
stack.top().info('tag1 and tag2 are added');
stack.pop();
stack.top().info('Only tag1 is added');
});
Caching Loggers
A logger can be associated with a category by calling setLogger(). This changes the value that is returned by logger() when the same category is provided. For example, you can assign permanent tag 'dog' to the 'dog' logger via:
loggers.setLogger('dog', loggers.child('dogTag'));
capcon.captureStdout(() => {
loggers.info({category: 'dog', message: 'woof' });
});
Notice that 'dogTag' appears in the log entry's tags above.
Log helpers
The library provides helper classes for logging the execution of various operations. The helpers generate and log a unique id as a tag. If an error occurs, the error is logged using the 'error' logging level.
TaskLogger
A message is logged with the 'begin' tag and an optional message. An operation is then invoked. If it succeeds, a message is logged with the 'end' tag. The provided function to execute can be synchronous or asynchronous (returns a Promise).
const TaskLogger = require('@goodware/log/TaskLogger');
Success example:
{
let output = '';
capcon.startCapture(process.stdout, function (stdout) {
output += stdout;
});
await TaskLogger.execute(loggers, () => true);
capcon.stopCapture(process.stdout);
output;
}
In the above example, two entries are logged with the same unique tag value. The first entry has the tag 'begin' and the second entry has the tag 'end.'
Use a child logger to use a specific level instead of the default level:
{
let output = '';
capcon.startCapture(process.stdout, function (stdout) {
output += stdout;
});
await TaskLogger.execute(loggers.child('info'), ()=>true);
capcon.stopCapture(process.stdout);
output;
}
If the function throws an error, it is logged and rethrown:
{
let output = '';
capcon.startCapture(process.stdout, (stdout) => output += stdout);
try {
await TaskLogger.execute(loggers, () => {
throw new Error('I will be logged');
});
} catch (error) {
// This error is logged by TaskLogger, so ignore it
}
capcon.stopCapture(process.stdout);
output;
}
All log entries have the same unique tag. The first entry has the tag 'begin' and the other entries have the tag 'error.'
MySqlLogger
Works with the mysql2 API. Logs a SQL statement and parameters. TODO: Provide example
RequestLogger
Works with the deprecated requests library. Logs an http request.
Redacting Data via the 'redact' Options Setting
'redact' provided via constructor options provides a simple way to remove properties from logged data without modifying any input data (properties are removed from copies only). Properties can optionally be removed recursively (the default is true). Nonrecursive redaction is also applied to nested Error objects.
// This example requires 6.2.1 or later
{
const optionsCopy = JSON.parse(JSON.stringify(options));
optionsCopy.redact = {
password: undefined, // { recursive: false } to disable recursive removal
};
const loggers2 = new Loggers(optionsCopy);
const data = {user: {password: 'Password123'}};
capcon.captureStdout(() => {
loggers2.info('password is redacted', data);
// Input data passed to all @goodware/log methods is immutable
loggers.info('password is not redacted', data);
});
}
Redacting Data via redact Events
'redact' events are emitted (potentially multiple times) when one log-related method is called. This event is intended for redacting properties from data objects. These events are emitted once for each object to be logged, including traversed Error objects.
Event listeners' return values are ignored. Event listeners are sent an event object consisting of category, level, context, and arg properties. Listeners can modify the event object's arg property. Alternatively, the object referenced by 'arg' can be modified. Mutate input data at your own risk!
The following example removes the response attribute from Error objects:
// This example requires 8.0.1 or later
loggers.on('redact', (item) => {
const { arg } = item;
// only process Errors with response properties
if (!(arg instanceof Error) || !arg.response) return;
// modify item's arg property instead of modifying arg
const copy = {...arg};
delete copy.response;
item.arg = copy;
});
capcon.captureStdout(() => {
const error = new Error('An http error occured');
error.response = 'I will be redacted';
error.statusCode = 404;
loggers.log(error);
});
In the above output, notice the 'response' property does not appear in the log entry's data.
log Events
'log' events are emitted prior to calling Winston's log() method. Due to error object traversal, multiple log events can be emitted when one log-related method is called. Because of transport tag filtering, the entry might not be logged.
Event listeners are sent a log entry object consisting of consisting of id, groupId, category, level, tags, message, and data properties. Listeners can modify event objects.
Flushing Messages to Transports
Use flush(), stop(), or restart() to wait for all log entries to be sent to all transports. All of these methods are slow because they close all transports. Calling these methods on any logger object is identical to calling the same method on Loggers instance creator and all of its child loggers.
await loggers.flush();
Log entries destined for CloudWatch Logs are buffered and sent in configurable batches. If you only want to flush CloudWatch Logs, call flushCloudWatchTransports() which doesn't close the transports. The file transport doesn't yet have an efficient flush capability.
Troubleshooting Hanging Processes
If a NodeJS process that uses this library doesn't terminate properly, the culprit may be a Loggers instance that hasn't been stopped (or at last recently flushed or restarted). Stopping, restarting, or flushing is especially recommended for AWS Lambda functions because they can be terminated abruptly, resulting in the loss of log entries.
await loggers.stop();
Thank you for using @goodware/log! If you have any questions, please post to the comments below or submit an issue at https://github.com/good-ware/js-log/issues.
no comments
sign in to comment