Introduction
This is the user guide for the JavaScript package @goodware/log which can be downloaded at https://www.npmjs.com/package/@goodware/log.
You can modify notebook to explore the package's functionality. No one else will see your edits. Go ahead and kick the tires!
@goodware/log
The @goodware/log package extends Winston3 with additional features such as tag-based filtering. It is intended for NodeJS runtimes including AWS Lambda. The package can log scalars, objects (even with cyclical references), arrays, and graphs of Error instances quickly and reliably. Log entries can be sent to the following transports: console (via winston-console-format), files (via winston-daily-rotate-file) in JSON format, and CloudWatch Logs (via winston-cloudwatch) in JSON format.
The package, which features a large unit test suite, has been servicing a commercial SaaS product for several years. It is BSD licensed.
Support
Please post questions, bug reports, and feature requests to https://github.com/good-ware/js-log/issues.
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 cool! 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://good-ware.github.io/js-log/Loggers.html#validateOptions].
const Loggers = require('@goodware/log');
const options = {
stage: process.env.NODE_ENV, // This is the value for the 'stage' key that appears in all
// log entries (aka meta key)
service: 'Example', // The name of this program (another meta key)
version: '1.0.0', // The program's version (another meta key)
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_CLOUDWATCH_REGION; AWS_DEFAULT_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, info, more, verbose, db, http, debug, silly
default: {
console: 'silly',
cloudWatch: 'off',
file: 'off',
errorFile: 'off',
},
briefConsole: {
console: {
level: 'info',
data: false,
},
},
},
};
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 set to 'silly'
Meta Keys
Notice the 'meta' keys in the log entry above, such as: timestamp and tags. Meta keys are the top-level properties of log entries. The list of meta keys are: timestamp, ms (elpased time between log entries), level, message, tags, category, id, groupId, depth, hostId, stage, version, service, stack, and transports. Additional keys can be specified via configuration.
Additional data to be logged appears under the data key.
This 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' key in the configuration object above.
Quieter Console
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:
options.console.data = false;
const briefConsole = new Loggers(options);
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 instances as well as the objects returned by logger() and child() support the following interface (https://good-ware.github.io/js-log/Loggers.html):
- start()
- stop()
- restart()
- ready (property)
- log()
- default() The default level is specified via option
- `level`() where `level` is a logging level name. Example: info()
- child()
- stack()
- logger(category [, loggerObject])
- parent() For child loggers to access their parent, which is either a Loggers object or a child logger
- loggers() For child loggers to access the Loggers object that created them
- winstonLogger()
- tags(), for combining tags
- context(), for combining context objects
- category() (mostly useful for retrieving the category assigned to logger objects)
- flush()
- 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' would have severity value 1 whereas 'warn' would have severity value 2.
Logging levels and their corresponding severities and colors are configurable. The default levels are fatal, error, warn, info, more, verbose, db, http, debug, silly. The following levels must exist: error, warn, debug.
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'. Both log entries are related via the groupId meta key:
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 the message to log. 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'));
});
Error instances can also be passed via context. Call stacks are not sent to console transports that are configured with a falsey value for the 'data' option.
capcon.captureStdout(() => {
briefConsole.log({error: new Error('Something went wrong')});
});
Categories and Loggers
Following Winston terminology, a category is the name of a logger object.
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
child(), isLevelEnabled(), log(), default(), and <level>() can be called in one of the following ways:
1. Traditional position-based arguments. 'null' or 'undefined' are allowed.
- tags: string, array, or object)
- message: any. For example, an Error object may be provided. Does not apply to child() and isLevelEnabled().
- context: any
- category: string
2. A single object for named arguments. The following optional properties may be provided:
- tags: array or object
- message: any. Does not apply to child() and isLevelEnabled().
- error: string or object. Does not apply to child() and isLevelEnabled().
- context: any
- category: string
Any additional keys are treated as if they were in the 'context' key.
3. If the first argument passed to a <level> method (e.g., info) is an array, it is treated as an array of tags. Does not apply to child() and isLevelEnabled().
4. If an Error object is provided as the first or second argument, the 'error' tag is added automatically. Does not apply to child() and isLevelEnabled().
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 set to warn because warn() was called.
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 the <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.
options.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 keys 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
},
},
};
loggers2 = new Loggers(options);
capcon.captureStdout(() => {
loggers2.silly('This is not logged'); // This is not logged because the console's level is set to 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'
});
Context
Use the 'context' parameter add context to logged messages.
'context' is typically an object whose keys will appear under the data meta key.
capcon.captureStdout(() => {
loggers.error('Operation failed', {error: new Error('An error'), counter: 5});
});
When 'message' is an object and it has the same keys that exist in 'context', 'context' 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 context 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 context with child().
Context can be 'built up' by chaining calls to logger() and/or child().
capcon.captureStdout(() => {
const child1 = loggers.child(['tag1'], { requestId: 'AEF1X' });
child1.info('First child');
const child2 = child1.child(null, { operationId: 10 });
child2.warn('Second child');
});
capcon.captureStdout(() => {
loggers.logger('dog').child('dogTag').child(null, { userId: 101 }).logger('poodle')
.debug('Woof!');
});
Named Logger Stacks
Logging context and other information can also be stored in stacks. 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 providing an object as the second parameter to logger(). 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.logger('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.
Success example:
const TaskLogger = require('@goodware/log/TaskLogger');
{
var output = '';
capcon.startCapture(process.stdout, function (stdout) {
output += stdout;
});
await TaskLogger.execute(loggers, ()=>true);
capcon.stopCapture(process.stdout);
output;
}
Use a child logger to use a specific level instead of the default level:
{
var 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:
{
var output = '';
capcon.startCapture(process.stdout, function (stdout) {
output += stdout;
});
try {
await TaskLogger.execute(loggers, ()=>{throw new Error('Failed');});
} catch (error) {
//
}
capcon.stopCapture(process.stdout);
output;
}
MySqlLogger
Works with the mysql2 API. Logs a SQL statement and parameters.
RequestLogger
Works with the deprecated requests library. Logs an http request.
Flushing Log Entries
To wait for all log entries to be sent to all transports, use flush(), stop(), or restart(). 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.
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.
await loggers.flush();
MySqlLogger
This helper logs SQL statements.
Stopping
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.
var output = '';
capcon.startCapture(process.stdout, function (stdout) {
output += stdout;
});
await loggers.stop();
capcon.stopCapture(process.stdout);
output;
Thank you for using the library!
no comments
sign in to comment