Before we get into databases, we have to address one of the attributes of a high- quality web application—managing logged information, including normal system activity, system errors, and debugging information. Logs give us an insight into the behavior of the system. They answer the following questions for the developers:
How much traffic is the application getting?
If it’s a website, which pages are people hitting the most?
How many errors occur and of what kind? Do attacks occur? Are malformed requests being sent?
Log management is also an issue. Unless managed well, log files can quickly fill the disk space. So, it becomes high priority to process old logs, hopefully extracting useful data before deleting the old logs. Commonly, this includes log rotation, which means regularly moving the existing log file to an archive directory and then starting with a fresh log file. Afterward, processing can occur to extract useful data, such as errors or usage trends. Just as your business analyst looks at profit/loss statements every few weeks, your DevOps team needs various reports to know whether there are enough servers to handle the traffic. Furthermore, log files can be screened for security vulnerabilities.
When we used the Express generator to initially create the Notes application, it configured an activity-logging system using morgan with the following code:
import { default as logger } from ‘morgan’;
..
app.use(logger(‘dev’));
This module is what prints messages about HTTP requests on the terminal window. We’ll look at how to configure this in the next section.
Another useful type of logging is debugging messages about an application. Debugging traces should be silent in most cases; they should only print information when debugging is turned on, and the level of detail should be configurable.
The Express team uses the debug package for debugging logs. These are turned on using the DEBUG environment variable, which we’ve already seen in use. We will see how to configure this shortly and put it to use in the Notes application. For more information, refer to https://www.npmjs.com/package/debug.
Finally, the application might generate uncaught exceptions or unhandled Promises. The uncaughtException and unhandledRejection errors must be captured, logged, and dealt with appropriately. We do not use the word must lightly; these errors must be handled.
Let’s get started.
1. Request logging with morgan
The morgan package generates log files from the HTTP traffic arriving on an Express application. It has two general areas for configuration:
- Log format
- Log location
As it stands, Notes uses the dev format, which is described as a concise status output for developers. This can be used to log web requests as a way to measure website activity and popularity. The Apache log format already has a large ecosystem of reporting tools and, sure enough, morgan can produce log files in this format.
To enable changing the logging format, simply change the following line in app.mjs:
app.use(logger(process.env.REQUEST_LOG_FORMAT || ‘dev’));
This is the pattern we are following throughout this book; namely, to have a default value baked into the application and to use an environment variable to override the default. If we don’t supply a configuration value through the environment variable, the program uses the dev format. Next, we need to run Notes, as follows:
$ REQUEST_LOG_FORMAT=common npm start
> notes@0.0.0 start /Users/david/chap07/notes
> cross-env node ./app.mjs
::1 – – [12/Jan/2020:05:51:21 +0000] “GET / HTTP/1.1” 304 –
::1 – – [12/Jan/2020:05:51:21 +0000] “GET
/vendor/bootstrap/css/bootstrap.min.css HTTP/1.1″ 304 –
::1 – – [12/Jan/2020:05:51:21 +0000] “GET
/assets/stylesheets/style.css HTTP/1.1″ 304 –
::1 – – [12/Jan/2020:05:51:21 +0000] “GET
/vendor/bootstrap/js/bootstrap.min.js HTTP/1.1″ 304 –
To revert to the previous logging output, simply do not set this environment variable. If you’ve looked at Apache access logs, this logging format will look familiar. The ::1 notation at the beginning of the line is IPV6 notation for localhost, which you may be more familiar with as 127.0.0.1.
Looking at the documentation for morgan, we learn that it has several predefined logging formats available. We’ve seen two of them—the dev format is meant to provide developer-friendly information, while the common format is compatible with the Apache log format. In addition to these predefined formats, we can create a custom log format by using various tokens.
We could declare victory on request logging and move on to debugging messages. However, let’s look at logging directly to a file. While it’s possible to capture stdout through a separate process, morgan is already installed on Notes and it provides the capability to direct its output to a file.
The morgan documentation suggests the following:
// create a write stream (in append mode)
const accessLogStream =
fs.createWriteStream(‘${ dirname}/access.log’, {flags: ‘a’});
// setup the logger
app.use(morgan(‘combined’, {stream: accessLogStream}));
However, this has a problem; it’s impossible to perform log rotation without killing and restarting the server. The phrase log rotation refers to a DevOps practice of keeping log file snapshots, where each snapshot covers a few hours of activity.
Typically, an application server will not keep a file handle continuously open to the log file, and the DevOps team can write a simple script that runs every few hours and uses the mv command to move log files around and the rm command to delete old files. Unfortunately, morgan, when configured as it is here, keeps a continuously open file handle to the log file.
Instead, we’ll use the rotating-file-stream package. This package even automates the log rotation task so that the DevOps team doesn’t have to write a script for that purpose.
First, install the package:
$ npm install rotating-file-stream –save
Then, add the following code to app.mjs:
import { default as rfs } from ‘rotating-file-stream’;
…
app.use(logger(process.env.REQUEST_LOG_FORMAT || ‘dev’, {
stream: process.env.REQUEST_LOG_FILE ?
rfs.createStream(process.env.REQUEST_LOG_FILE, {
size: ’10M’, // rotate every 10 MegaBytes written
interval: ‘1d’, // rotate daily
compress: ‘gzip’ // compress rotated files
})
: process.stdout
}));
In the import section at the top, we’re loading rotating-file-stream as rfs. If the REQUEST_LOG_FILE environment variable is set, we’ll take that as the filename to record to. The stream argument to morgan simply takes a writable stream.
If REQUEST_LOG_FILE is not set, we use a ?: operator to supply the value of process.stdout as the writable stream. If it is set, then we use rfs.createStream to create a writable stream that handles log rotation through the rotating-file- stream module.
In rfs.createStream, the first argument is the filename of the log file and the second is an options object describing the behavior to use. Quite a comprehensive set of options are available for this. The configuration shown here rotates the log file when it reaches 10 megabytes in size (or after 1 day) and the rotated log file is compressed using the gzip algorithm.
It’s possible to set up multiple logs. For example, if we wanted to log to the console, in addition to logging to the file, we could add the following logger declaration:
if (process.env.REQUEST_LOG_FILE) {
app.use(logger(process.env.REQUEST_LOG_FORMAT || ‘dev’));
}
If the REQUEST_LOG_FILE variable is set, the other logger will direct logging to the file. Then, because the variable is set, this logger will be created and will direct logging to the console. Otherwise, if the variable is not set, the other logger will send logging to the console and this logger will not be created.
We use these variables as before, specifying them on the command line, as follows:
$ REQUEST_LOG_FILE=log.txt REQUEST_LOG_FORMAT=common DEBUG=notes:* node ./app.mjs
With this configuration, an Apache format log will be created in log.txt. After making a few requests, we can inspect the log:
$ ls -l log.txt
-rw-r–r– 1 david admin 18831 Jan 17 21:10 log.txt
$ head log.txt
::1 – – [18/Jan/2020:04:32:02 +0000] “GET / HTTP/1.1” 304 –
::1 – – [18/Jan/2020:04:32:02 +0000] “GET
/assets/vendor/bootstrap/css/bootstrap.min.css HTTP/1.1″ 304 –
::1 – – [18/Jan/2020:04:32:02 +0000] “GET
/assets/stylesheets/style.css HTTP/1.1″ 304 –
::1 – – [18/Jan/2020:04:32:02 +0000] “GET
/assets/vendor/jquery/jquery.min.js HTTP/1.1″ 304 –
As expected, our log file has entries in Apache format. Feel free to add one or both of these environment variables to the script in package.json as well.
We’ve seen how to make a log of the HTTP requests and how to robustly record it in a file. Let’s now discuss how to handle debugging messages.
2. Debugging messages
How many of us debug our programs by inserting console.log statements? Most of us do. Yes, we’re supposed to use a debugger, and yes, it is a pain to manage the console.log statements and make sure they’re all turned off before committing our changes. The debug package provides a better way to handle debug tracing, which is quite powerful.
The Express team uses DEBUG internally, and we can generate quite a detailed trace of what Express does by running Notes this way:
$ DEBUG=express:* npm start
This is pretty useful if you want to debug Express. However, we can use this in our own code as well. This works similarly to inserting console.log statements, but without having to remember to comment out the debugging code.
To use this in our code, add the following declaration to the top of any module where you want the debugging output:
import { default as DBG } from ‘debug’;
const debug = DBG(‘notes:debug’);
const dbgerror = DBG(‘notes:error’);
This creates two functions—debug and dbgerror—which will generate debugging traces if enabled. The Debug package calls functions debuggers. The debugger named debug has a notes:debug specifier, while dbgerror has a notes:error specifier. We’ll talk in more detail about specifiers shortly.
Using these functions is as simple as this:
debug(‘some message’);
..
debug(‘got file ${fileName}’);
When debugging is enabled for the current module, this causes a message to be printed. If debugging is not enabled for the current module, no messages are printed. Again, this is similar to using console.log, but you can dynamically turn it on and off without modifying your code, simply by setting the DEBUG variable appropriately.
The DEBUG environment variable contains a specifier describing which code will have debugging enabled. The simplest specifier is *, which is a wildcard that turns on every debugger. Otherwise, debug specifiers use the identifer:identifier format. When we said to use DEBUG=express:*, the specifier used express as the first identifier and used the * wildcard for the second identifier.
By convention, the first identifier should be the name of your application or library. So, we used notes:debug and notes:error earlier as specifiers. However, that’s just a convention; you can use any specifier format you like.
To add debugging to Notes, let’s add a little more code. Add the following to the bottom of app.mjs:
server.on(‘request’, (req, res) => {
debug(‘${new Date().toISOString()} request ${req.method}
${req.url}’);
});
This is adapted from the httpsniffer.mjs example from Chapter 4, HTTP Servers and Clients, and for every HTTP request, a little bit of information will be printed.
Then, in appsupport.mjs, let’s make two changes. Add the following to the top of the onError function:
export function onError(error) {
dbgerror(error);
..
}
This will output an error trace on any errors captured by Express.
Then, change onListening to the following:
export function onListening() {
const addr = server.address();
const bind = typeof addr === ‘string’
? ‘pipe ‘ + addr
: ‘port ‘ + addr.port;
debug(‘Listening on ${bind}’);
}
This changes the console.log call to a debug call so that a Listening on message is printed only if debugging is enabled.
If we run the application with the DEBUG variable set appropriately, we get the following output:
$ REQUEST_LOG_FORMAT=common DEBUG=notes:* node ./app.mjs
notes:debug Listening on port 3000 +0ms
notes:debug 2020-01-18T05:48:27.960Z request GET /notes/add +0ms
::1 – – [18/Jan/2020:05:48:28 +0000] “GET /notes/add HTTP/1.1” 304 –
notes:debug 2020-01-18T05:48:28.143Z request GET
/assets/vendor/bootstrap/css/bootstrap.min.css +183ms
::1 – – [18/Jan/2020:05:48:28 +0000] “GET
/assets/vendor/bootstrap/css/bootstrap.min.css HTTP/1.1″ 304 –
…
Look at this carefully and you’ll see that the output is both the logging output from morgan and the debugging output from the debug module. The debugging output, in this case, starts with notes:debug. The logging output is, because of the REQUEST_LOG_FORMAT variable, in Apache format.
We now have a debug tracing system that’s ready to be used. The next task to cover is seeing whether it’s possible to capture this or other console output in a file.
3. Capturing stdout and stderr
Important messages can be printed to process.stdout or process.stderr, which can be lost if you don’t capture the output. It is best practice to capture this output for future analysis because there can be useful debugging information contained in it. An even better practice is to use a system facility to capture these output streams.
A system facility can include a process manager application that launches applications while connecting the standard output and standard error streams to a file.
While it lacks this sort of facility, it turns out that JavaScript code running in Node.js can intercept the process.stdout and process.stderr streams. Among the available packages, let’s look at capture-console. For a writable stream, this package will invoke a callback function that you provided for any output.
The last administrative item to cover is ensuring we capture otherwise uncaught errors.
4. Capturing uncaught exceptions and unhandled rejected Promises
Uncaught exceptions and unhandled rejected Promises are other areas where important information can be lost. Since our code is supposed to capture all errors, anything that’s uncaught is an error on our part. Important information might be missing from our failure analysis if we do not capture these errors.
Node.js indicates these conditions with events sent by the process object, uncaughtException and unhandledRejection. In the documentation for these events, the Node.js team sternly says that in either condition, the application is in an unknown state because something failed and that it may not be safe to keep the application running.
To implement these handlers, add the following to appsupport.mjs:
process.on(‘uncaughtException’, function(err) {
console.error(‘I’ve crashed!!! – ${(err.stack || err)}’);
});
import * as util from ‘util’;
process.on(‘unhandledRejection’, (reason, p) => {
console.error(‘Unhandled Rejection at: ${util.inspect(p)} reason:
${reason}’);
});
Because these are events that are emitted from the process object, the way to handle them is to attach an event listener to these events. That’s what we’ve done here.
The names of these events describe their meaning well. An uncaughtException event means an error was thrown but was not caught by a try/catch construct. Similarly, an unhandledRejection event means a Promise ended in a rejected state, but there was no .catch handler.
Our DevOps team will be happier now that we’ve handled these administrative chores. We’ve seen how to generate useful log files for HTTP requests, how to implement debug tracing, and even how to capture it to a file. We wrapped up this section by learning how to capture otherwise-uncaught errors.
We’re now ready to move on to the real purpose of this chapter—storing notes in persistent storage, such as in a database. We’ll implement support for several database systems, starting with a simple system using files on a disk.
Source: Herron David (2020), Node.js Web Development: Server-side web development made easy with Node 14 using practical examples, Packt Publishing.