February 20, 2019

Fix Morgan logging with Docker and Nginx

Application logging is important. This week, we find out how to accurately log your NodeJS app running inside Docker

I am a big fan of Docker and put most of my web applications and web services into containers. I am also a big fan of application logging, however I recently ran into a problem where the requester's address was not being properly displayed in the log file. In this post, we will look at the problem and how to solve it.

We will be using a very basic NodeJS app, with one route. Lets start off by creating and initializing our Node app and installing our dependencies. I set my entry point to server.js, and kept the rest of the default values.

npm init what-is-my-ip
cd what-is-my-ip
npm i express morgan moment-timezone
npm i --save-dev nodemon

Create a new file and call name is server.js

server.js

const express = require('express');
const morgan = require('morgan');
const fs = require('fs');
const path = require('path');

const app = express();
const port = 9002;

// Create write stream to save log
var accessLogStream = fs.createWriteStream(path.join(__dirname, 'logs', 'access.log'), { flag: 'a' });

app.use(morgan('combined', { stream: accessLogStream }));

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

app.listen(port, () => {
    console.log('Server started on port', port);
});

We are using morgan for logging our requests into a file called access.log. If you haven't used morgan before, be sure to check out their Github here.

When you run your app, you will see a logs folder with your access.log file.

Docker

Now, lets put our app into a docker container. Create a Dockerfile inside your projects folder, and add the following.

FROM node:10.13-alpine
ENV NODE_ENV production
WORKDIR /usr/src/app
COPY ["package.json", "package-lock.json*", "npm-shrinkwrap.json*", "./"]
RUN npm install --production --silent && mv node_modules ../
COPY . .
EXPOSE 9002
CMD node server.js

If you are not familiar with Docker, the above file will take our app and create a container for us.

The Problem

You won't notice the problem until you run your docker container on your web server. After you have moved your files over, start your docker container.

docker build -t what-is-my-ip .

Run the above comment inside your project folder. This will build your docker image based off the information in your Dockerfile.

docker run -d -e NODE_ENV='production' -p 9002:9002 -v /tmp/logs:/usr/src/app/logs --name what-is-my-ip what-is-my-ip:latest

This will run your docker container.

  • -d - Run the docker image in the background
  • -e - set environment variables
  • -p - set port forwarding
  • -v - mount a volume, which will be used to persist our log files. They will be stores in /tmp/logs on our server
  • --name - Allows us to set a name for our docker container
  • what-is-my-ip:latest - This is the docker image we are using

Once your application is started, navigate to it in your browser, and then check the /tmp/logs/access.log file.

 cat access.log
::ffff:172.17.0.1 - - [18/Feb/2019:01:04:28 +0000] "GET / HTTP/1.0" 200 21 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.109 Safari/537.36"
::ffff:172.17.0.1 - - [18/Feb/2019:01:04:29 +0000] "GET /favicon.ico HTTP/1.0" 404 150 "https://ip.offhourscoding.com/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.109 Safari/537.36"

You will notice that the IPs that are being shown are 172.17.x.x. These are the default IPs used in Docker when using bridge networking. You can find out more about Docker's networking here.

Although the log shows us everything else, it would still be nice to have the proper IP address.

The Solution

The first thing we are going to do happens in our web server configuration. I am using Nginx, and have our app running as a subdomain. We need to tell Nginx to forward the remote address inside the header.

nginx.conf

server {
        server_name ip.offhourscoding.com;
        location / {
                proxy_set_header X-Real-IP $remote_addr;
                proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
                proxy_set_header X-NginX-Proxy true;
                proxy_pass http://127.0.0.1:9002;
                proxy_ssl_session_reuse off;
                proxy_set_header Host $http_host;
                proxy_cache_bypass $http_upgrade;
                proxy_redirect off;
        }

Next, we are going to create a new module that will contain our custom logging format.

logger.js

const morgan = require('morgan');
const moment = require('moment-timezone');
const fs = require('fs');
const path = require('path');

module.exports = logger;

function logger() {

   // Create daily log file
   // const datetime = new Date();
   // const month = (datetime.getMonth() < 9) ? '0' + (datetime.getMonth() + 1) : datetime.getMonth() + 1;
   // const day = (datetime.getDay() < 9) ? '0' + (datetime.getDay() + 1) : datetime.getDay() + 1;
   // const timestamp = month + day + datetime.getFullYear();
   // const logStream = fs.createWriteStream(path.join(__dirname, 'logs', timestamp + '.log'), { flags: 'a' });
   const logStream = fs.createWriteStream(path.join(__dirname, 'logs', 'access.log'), { flags: 'a' });

   // Create custom client IP token - workaround for docker/nginx proxy
   morgan.token('clientaddr', (req, res) => {
       return req.headers['x-forwarded-for'] || req.connection.remoteAddress;
   });

   // Create custom date token with proper timezone infomation - fixes logs so they are not in UTC
   morgan.token('date', (req, res, tz) => {
       return moment().tz(tz).format();
   });

   // Build custom morgan logging format
   morgan.format('myformat', ':clientaddr - :clientaddr [:date[America/New_York]] ":method :url HTTP/:http-version" :status :res[content-length] ":referrer" ":user-agent"');

   morgan('myformat', { stream: logStream });

   //return next(morgan('myformat', {stream: logStream} ));
   return function log(req, res, next) {
       req.app.use(morgan('myformat', { stream: logStream }));

       return next();
   };
}

First, we set the filename of our log file. For this example, we will continue to use access.log, but I have also provided a way of creating a new log file for each day.

The next part is the important one. We create a custom morgan token, which grabs the remote IP address from the request header we enabled in Nginx.

By default, morgan uses UTC time which is fine; but I prefer it showing in my local timezone. I create another custom token and use moment to format the timestamp.

We then take all of these parts and put them into a format for our log.

Finally, we tell morgan to use our custom format and save it to our log file.

Now that we have setup our logger, we have to modify our server.js file to use it.

server.js

const express = require('express');
const logger = require('./logger');
const morgan = require('morgan');
const fs = require('fs');
const path = require('path');

const app = express();
const port = 9002;

app.use(logger());

app.get('/', (req, res) => {
    const ip = req.headers['x-forwarded-for'] || req.connection.remoteAddress;
    res.send('<h1>Your IP is ' + ip + '</h1>');
});

app.listen(port, () => {
    console.log('Server started on port', port);
});

We replace our morgan logic with our custom logger.

We are finished making our changes. It's time to see what our log now looks like.

Testing It

After you have moved your files to your server, stop your previous docker container, and recreate it with our new code.

docker build -t what-is-my-ip .
docker stop what-is-my-ip && docker rm what-is-my-ip
docker run -d -e NODE_ENV='production' -p 9002:9002 -v /tmp/logs:/usr/src/app/logs --name what-is-my-ip what-is-my-ip:latest

Open your browser and go to your app again. Inside our log file, you will now see your public IP, instead of the Docker bridge IPs.

access.log

cat access.log
199.167.137.22 - 199.167.137.22 [2019-02-17T20:34:06-05:00] "GET /favicon.ico HTTP/1.0" 404 150 "https://ip.offhourscoding.com/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.109 Safari/537.36"
199.167.137.22 - 199.167.137.22 [2019-02-17T20:34:06-05:00] "GET /favicon.ico HTTP/1.0" 404 150 "https://ip.offhourscoding.com/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.109 Safari/537.36"

Conclusion

If you are using Docker's bridge networking, which is the default, the above solution will be able to provide you with more accurate log files.

I hope this was helpful. Have you ever run into this problem before? How did you solve it?

All of the code can be found on my Github. Feel free to check it out, and leave your comments below.