The Morgan package has two general areas for configuration:

As it stands, the code uses the dev format, which is described as a concise status output meant 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. It also has a nice method to generate a custom log format, if you prefer.

To change the format, simply change this line in app.js:

app.use(logger(process.env.REQUEST_LOG_FORMAT || 'dev'));

Then run Notes as follows:

$ REQUEST_LOG_FORMAT=common npm start

> [email protected] start /Users/david/chap07/notes
> node ./bin/www
::1 - - [12/Feb/2016:05:51:21 +0000] "GET / HTTP/1.1" 304 -
::1 - - [12/Feb/2016:05:51:21 +0000] "GET /vendor/bootstrap/css/bootstrap.min.css HTTP/1.1" 304 -
::1 - - [12/Feb/2016:05:51:21 +0000] "GET /stylesheets/style.css HTTP/1.1" 304 -
::1 - - [12/Feb/2016: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.

According to the Morgan documentation, we can even pass a format string this way. If we need a custom log format, it's easy to define one.

We can declare victory on request logging and move on to debugging messages. However, let's look at logging this to a file directly. While it's possible to capture stdout through a separate process, Morgan is already installed in Notes and it does provide the capability to direct its output to a file.

The Morgan documentation suggests this:

// create a write stream (in append mode)
var accessLogStream = fs.createWriteStream(
            __dirname + '/access.log', {flags: 'a'})

// setup the logger
app.use(morgan('combined', {stream: accessLogStream}));

But this has a problem; it's impossible to perform log rotation without killing and restarting the server. Instead, we'll use their file-stream-rotator package.

First, install the package:

$ npm install file-stream-rotator --save

Then we add this code to app.js:

var FileStreamRotator = require('file-stream-rotator');
..
var accessLogStream;
if (process.env.REQUEST_LOG_FILE) {
    var logDirectory = path.dirname(process.env.REQUEST_LOG_FILE);
    fs.existsSync(logDirectory) || fs.mkdirSync(logDirectory);
    accessLogStream = FileStreamRotator.getStream({
      filename: process.env.REQUEST_LOG_FILE,
      frequency: 'daily',
      verbose: false
    });
}
..
app.use(logger(process.env.REQUEST_LOG_FORMAT || 'dev', {
    stream: accessLogStream ? accessLogStream : process.stdout
}));

Here, we're using an environment variable, REQUEST_LOG_FILE, to control whether to send the log to stdout or to a file. The log can go into a directory, and the code will automatically create that directory if it doesn't exist. By using the file-stream-rotator (https://www.npmjs.com/package/file-stream-rotator), we're guaranteed to have log file rotation with no extra systems required.

You can generate quite a detailed trace of what Express does by running Notes this way:

$ DEBUG=express:* npm start

This is a pretty useful thing if you want to debug Express. But, we can use this in our own code as well. This is like debugging with the console.log statements, but without having to remember to comment out the debugging code.

It is very simple to enable debugging in a module:

var debug = require('debug')('module-name');
..
debug('some message');
..
debug('got file %s', fileName);

Important messages can be printed to process.stdout or process.stderr, which can be lost if you don't capture that output. The Twelve Factor model suggests using a system facility to capture these output streams. With Notes, we'll use PM2 for that purpose, which we'll cover in Chapter 10, Deploying Node.js Applications.

The logbook module (https://github.com/jpillora/node-logbook) offers some useful capabilities to not only capture process.stdout and process.stderr, but to send that output to useful places.

Uncaught exceptions is another area where important information can be lost. This is easy to fix in the Notes application:

var error = require('debug')('notes:error');

process.on('uncaughtException', function(err) {
  error("I've crashed!!! - "+ (err.stack || err));
});
..
if (app.get('env') === 'development') {
  app.use(function(err, req, res, next) {
    // util.log(err.message);
    res.status(err.status || 500);
    error((err.status || 500) +' '+ error.message);
    res.render('error', {
      message: err.message,
      error: err
    });
  });
}
..
app.use(function(err, req, res, next) {
  // util.log(err.message);
  res.status(err.status || 500);
  error((err.status || 500) +' '+ error.message);
  res.render('error', {
    message: err.message,
    error: {}
  });
});

The Debug package has a convention we're following. For an application with several modules, all debugger objects should use the naming pattern app-name:module-name. In this case, we used notes:error that will be used for all error messages. We could also use notes:memory-model or notes:mysql-model for debugging different models.

While we were setting up the handler for uncaught exceptions, it is also a good idea to add error logging in the error handlers.