Logging all requests in Node.js/Express

Question

In my small node.js application, using express, I wanted to log all the incoming requests, so I ended up with this:

var bodyParser = require('body-parser');

module.exports = function(app) {
   app.set("port", 50001);
   app.set("json spaces", 2);
   app.use(bodyParser.json());
   app.use(function (error, req, res, next) {
      app.logger.info("received from "+req.get("X-Forwarded-For")+" : "+req.method+" "+req.originalUrl+" (Authorization: "+req.get("Authorization")+")");
      //does not work if json is malformed
      //app.logger.info("content :"+JSON.stringify(req.body));
      if (error /*instanceof SyntaxError*/) {
         res.status(400);
         app.logger.error(error);
         res.json({ error:{msg: error.message}});
      } else {
         next();
      }
   });
   app.use(app.auth.initialize());
};

Unfortunately, I only get the logs via the app.logger.info line when there's an error (in my case a malformed JSON string in the body). What am I missing here?

Solution 1

Expressjs adapts its functionality based on what type of callback you give it (this is not common in JS libraries so it is not surprising that people get confused by it).

If you do this where your callback has four arguments:

app.use(function(error, req, res, next) {...});

then Express assumes this is an error-only middleware handler and will only be called when there are errors. In the express doc, see the section labeled Error-handling middleware. Note this specific part of that page:

Define error-handling middleware functions in the same way as other middleware functions, except with four arguments instead of three, specifically with the signature (err, req, res, next)):

And, here's a whole section of the documentation devoted to error handling middleware.

If you use just three arguments:

app.use(function(req, res, next) {...});

then, it is a normal middleware that is called when there are not errors. I'm not sure if they provide a single way to get both. But, certainly as a workaround, you could put your logging code into a function and then call that function from two separate middleware handlers, one for errors and one for non-errors.

Solution 2

Use morgan https://github.com/expressjs/morgan

Install morgan

$ npm install morgan

Include morgan in the index.js or app.js or server.js file (The file that pointed by the script tag in the package.json)

var morgan = require('morgan')

Then add below before all the app call.

app.use(morgan('combined'))

Complete example

var express = require('express')
var morgan = require('morgan')

var app = express()

app.use(morgan('combined'))

app.get('/', function (req, res) {
  res.send('hello, world!')
})

A sample output line looks like this:

::1 - - [31/May/2021:09:03:14 +0000] "GET / HTTP/1.1" 200 2078 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.77 Safari/537.36"

Solution 3

DEBUG='*' or DEBUG='express:router' environment variable

It does not show a lot of information about the request, but it does show the path and method, which might be enough for basic applications, and is convenient as it does not require any extra setup.

DEBUG='*' enables all logs and is slightly easier to type:

DEBUG='*' ./app.js

or the more specific DEBUG='express:router' is what you will generally want in a complex application with a lot of middleware, otherwise the DEBUG='*' could produce mountains of output:

DEBUG='express:router' ./app.js

E.g. with the hello world:

#!/usr/bin/env node

const express = require('express')
const app = express()
const port = 3000

app.get('/', (req, res) => {
  res.send('Hello World!')
})

app.listen(port, () => {
  console.log(`Example app listening at http://localhost:${port}`)
})

Then as I play on the browser with different URLs I can see logs such as:

  express:router dispatching GET / +3m
  express:router query  : / +0ms
  express:router expressInit  : / +0ms
  express:router dispatching GET /asdf +10s
  express:router query  : /asdf +0ms
  express:router expressInit  : /asdf +0ms
  finalhandler default 404 +3m
  express:router dispatching GET /asdf?qwer=zxcv +17s
  express:router query  : /asdf?qwer=zxcv +0ms
  express:router expressInit  : /asdf?qwer=zxcv +0ms
  finalhandler default 404 +17s

Documentation at: https://expressjs.com/en/guide/debugging.html

Tested on express 4.17.1.

Solution 4

npm install body-parser

npm install morgan-body

and use this snippet,

const express = require('express')
const morganBody = require("morgan-body")
const bodyParser = require("body-parser")

const app = express()
const port = 8888

// must parse body before morganBody as body will be logged
app.use(bodyParser.json());

// hook morganBody to express app
morganBody(app, {logAllReqHeader:true, maxBodyLength:5000});

app.get('/', (req, res) => {
  res.send('Hello World!')

})

app.listen(port, () => {
  console.log(`Example app listening at http://localhost:${port}`)
})

View more solutions