Having comprehensive and easily accessed website logs are essential for web application troubleshooting and security. This website logs every HTTP request, exception, error, and other interesting things.

When you start logging the requests that hit your website, you'll probably find frequent attacks. In the realm of computer security, an attack is an attempt do do something nefarious, that is not necessarily successful. For instance, in the below log, you can see two unsuccessful attempt to access an "administrator" page, using a url that doesn't exist.

Note: I removed the IP addresses.

Website Log File

Generating Log Files

It's quite easy to log requests with Express. For this website, I created a module named "logging". Its setup method is called from the main app.js module, as the application starts up.

app.js:

...
var logging = require('./libs/logging');
...

var app = express();
...
logging.setup(app);

Logging is configured in logging.js. This website uses the morgan module to log every HTTP request, and uses log4js to write the HTTP log entries to a file. Explicit log messages are written with calls like:

global.logger.info("log message");

The morgan logging module allows custom tokens to appear in the log. For example, this website uses an 'ipAddr' custom token. Whenever morgan needs to log that token, it calls a custom callback to retrieve the value. In my callback, I call utils.getIPAddress to retrieve the request's IP address. The same callback mechanism is used to include user-agent values in the log.

In the morgan "stream" configuration, the write method uses log4js to write the log to a text file.

libs/logging.js:

var morgan = require('morgan');
var log4js = require('log4js');
var config = require('../libs/config');
var utils = require('../libs/utils');

exports.setup = function (app) {
    log4js.configure(config.logConfig);

    global.logger = log4js.getLogger('dev');

    var theAppLog = global.logger;

    // Use the IP address in the request header, if necessary.
    morgan.token('ipAddr', function getId(req) {
        return utils.getIPAddress(req);
    });

    // Retrieve user agent from request header.
    morgan.token('user-agent', function getId(req) {
        return req.headers['user-agent'];
    });

    var theHTTPLog = morgan(":ipAddr :method :http-version :url :referrer :user-agent :status :response-time", {
        "stream": {
            write: function (str) {
                theAppLog.debug(str.trim());
            }
        }
    });

    app.use(theHTTPLog);
};

This website's log4js logger uses a "dateFile" appender. This appender appends all log messages to a file named "log.log", until midnight, at which time the "log.log" file is renamed to a file containing the previous day's date, for example, "log.log-2015-10-17".

libs/config.js:

...
if (app.get('env') === "development") {
    exports.logFolder = '/temp/logs/';
}
else if (app.get('env') === 'production') {
    exports.logFolder = '/home/ericbtco/logs/ericbt.com/';
}

exports.currentLogFileName = 'log.log';

exports.logConfig = {
    appenders: [
        {
            type: 'console'
        },
        {
            "type": "dateFile",
            filename: exports.logFolder + exports.currentLogFileName,
            "pattern": "-yyyy-MM-dd",
            "alwaysIncludePattern": false,
            category: 'dev'
        }
    ]
};

exports.maxLogFiles = 15;
...

My hosting provider stores each request's IP address in a custom HTTP header named "x-forwarded-for". The getIPAddress function, which is automatically called when an IP address is being logged, returns the "x-forwarded-for" header value, if available. Otherwise it returns the request's connection.remoteAddress value.

libs/utils.js:

...
exports.getIPAddress = function(req) {
    return req.headers['x-forwarded-for'] || req.connection.remoteAddress;
};
...

Displaying Log Files

This website allows administrators to choose and display log files. The UI for log file retrieval is specified by the logs.ejs template. Note, this website uses EJS templates. If you are using a different template engine, you'll need to convert logs.ejs to the format required by your template engine.

views/admin/logs.ejs:

<% layout('../layout') -%>
<% block('scripts', '<script type="text/javascript" src="/javascripts/jquery-validate.min.js"></script>') -%>
<% block('scripts', '<script type="text/javascript" src="/javascripts/lognavigate.min.js"></script>') -%>
<h1><%= title %></h1>

<table>
    <tbody>
        <tr>
            <td>
                <form action="/admin/logs" method="POST">
                    <select id="selection_" name="selection" required>
                        <option value="">(Select)</option>

                        <% for (var i = 0; i < logs.length; i++) { var log = logs[i]; %>
                        <option value="<%=i%>" <%=fileName === log ? 'selected' : ''%>><%=log%></option>
                        <% } %>
                    </select>
                    <span class="checkbox-span">
                        <input type="checkbox" id="excludeMyIPAddress" name="excludeMyIPAddress" <%=excMyIPAddr ? 'checked' : ''%> />
                        <label for="excludeMyIPAddress">Exclude my IP Address</label>
                    </span>
                    <span class="checkbox-span">
                        <input type="checkbox" id="excludeBots" name="excludeBots" <%=excBots ? 'checked' : ''%> />
                        <label for="excludeBots">Exclude Bots</label>
                    </span>
                    <button type="submit">View Log</button>
                </form>
            </td>
            <% if (logContent != null) { %>
            <td>
                <button name="BottomButton" id="BottomButton">Bottom</button>
            </td>
            <% } %>
        </tr>
    </tbody>
</table>
<% if (logContent != null) { %>
<hr/>
<pre>
    <%= logContent%>
</pre>
<button name="TopButton" id="TopButton">Top</button>
<% } %>

stylesheet.css:

...
.checkbox-span
{
	margin-left: 0.5em;
	margin-right: 0.5em;
}

.checkbox-span input
{
	margin-right: 0.5em;
}
...

The main app.js module calls the "logs" controller setup method when the app is started.

app.js:

...
var controllers =
    [
        ... "logs", ...
    ];

controllers.forEach(function(value) {
    var controller = require('./controllers/' + value);
    controller.setup(app);
});
...

The logs controller enumerates log filenames, and retrieves log file contents, with line-by-line filtering.

controllers/logs.js:

var logModel = require('../models/logs');
var config = require('../libs/config');
var utils = require('../libs/utils');

function setupGetLogs(app) {
    app.get('/admin/logs', function (req, res) {
        logModel.getLogFiles(config.logFolder, function(error, data) {
            if (!error) {
                res.render('../views/admin/logs',
                    {
                        title: 'Logs',
                        logs: data,
                        fileName: '',
                        excMyIPAddr: false,
                        excBots: false,
                        logContent: null
                    });
            }
            else {
                res.redirect('/error?message=3');
            }
        });
    });
}

function setupPostLogs(app) {
    app.post('/admin/logs', function (req, res) {
        var fileIndex = parseInt(req.body.selection);

        var excludeMyIPAddress = req.body.excludeMyIPAddress === "on";
        var excludeBots = req.body.excludeBots === "on";

        logModel.getLogContents(fileIndex, excludeMyIPAddress, utils.getIPAddress(req), excludeBots, function (error, logs, fileName, contents) {
            if (!error) {
                res.render('../views/admin/logs',
                    {
                        title: 'Logs',
                        logs: logs,
                        fileName: fileName,
                        excMyIPAddr: excludeMyIPAddress,
                        excBots: excludeBots,
                        logContent: contents
                    });
            }
            else {
                global.logger.error('logs: ' + error);
                res.redirect('/error?message=4');
            }
        });
    });
}

exports.setup = function(app) {
    global.logger.info("logs controller setup");

    setupGetLogs(app);
    setupPostLogs(app);
};

The logs model retrieves the log files from the log folder, sorts them by date, and retrieves a given log file's contents. The contents optionally includes log messages with the user's IP address, and log messages from "bots" or "spiders", based on the checkboxes that the user checked or cleared.

The botRegex regular expression is used to determine if a request's User-Agent field identifies the requesting system as a bot. But it is only partially effective, as many bots do not identify themselves with User-Agent values, or specify deliberately misleading User-Agent values.

var botRegex = /Yahoo! Slurp|bot|Feedly|NewsBlur|spider/i;

The line-reader module iterates through each line of the log file, asynchronously. As each line becomes available, the line is either included or excluded, based on the filtering logic.

will detect some but not all bots. Some bots do not identify themselves with an obvious User-Agent header value.

/models/logs.js:

var fs = require('fs');
var config = require('../libs/config');
var lineReader = require('line-reader');

function sortLogFileNames(a, b) {
    if (a === b) {
        return 0;
    }
    else if (a === config.currentLogFileName) {
        return -1;
    }
    else if (b === config.currentLogFileName) {
        return 1;
    }
    else if (a < b) {
        return 1;
    }
    else {
        return -1;
    }
}

function sortLogs(data) {
    return data.sort(sortLogFileNames).slice(0, Math.min(data.length - 1, config.maxLogFiles));
}

exports.getLogFiles = function(logFolder, callback) {
    fs.readdir(logFolder, function(error, data) {
        callback(error, sortLogs(data));
    });
};

exports.getLogContents = function(logIndex, excludeIPAddress, ipAddress, excludeBots, callback) {
    var fileContentsCallback = function(error, logs, data) {
        if (error) {
            global.logger.error('getLogContents: ' + error);
        }

        callback(error, logs, logs[logIndex], data);
    };

    fs.readdir(config.logFolder, function(error, logs) {
        if (!error) {
            logs = sortLogs(logs);

            if (logIndex < 0 || logIndex >= logs.length) {
                error = "log file index out of range";
            }

            if (!error) {
                var lines = "";
                var botRegex = /Yahoo! Slurp|bot|Feedly|NewsBlur|spider/i;

                lineReader.eachLine(config.logFolder + logs[logIndex], function(line, last) {
                    if (!((excludeIPAddress && line.indexOf(ipAddress) > -1) || (excludeBots && botRegex.test(line)))) {
                        if (!last) {
                            line += '\n';
                        }

                        lines += line;
                    }

                    if (last) {
                        fileContentsCallback(error, sortLogs(logs), lines);
                    }
                })
            }
            else {
                fileContentsCallback(error);
            }
        }
        else {
            fileContentsCallback(error);
        }
    });
};

I have always been fond of logs