2013-06-04 06:17:36 +08:00
|
|
|
"use strict";
|
2011-07-12 11:02:48 +08:00
|
|
|
var levels = require("./levels");
|
2015-03-10 14:13:49 +08:00
|
|
|
var _ = require('underscore');
|
2015-03-09 03:35:54 +08:00
|
|
|
var DEFAULT_FORMAT = ':remote-addr - -' +
|
|
|
|
' ":method :url HTTP/:http-version"' +
|
|
|
|
' :status :content-length ":referrer"' +
|
2013-06-04 06:17:36 +08:00
|
|
|
' ":user-agent"';
|
2011-04-07 08:19:18 +08:00
|
|
|
/**
|
|
|
|
* Log requests with the given `options` or a `format` string.
|
|
|
|
*
|
|
|
|
* Options:
|
|
|
|
*
|
|
|
|
* - `format` Format string, see below for tokens
|
2013-05-11 22:17:23 +08:00
|
|
|
* - `level` A log4js levels instance. Supports also 'auto'
|
2011-04-07 08:19:18 +08:00
|
|
|
*
|
|
|
|
* Tokens:
|
|
|
|
*
|
|
|
|
* - `:req[header]` ex: `:req[Accept]`
|
|
|
|
* - `:res[header]` ex: `:res[Content-Length]`
|
|
|
|
* - `:http-version`
|
|
|
|
* - `:response-time`
|
|
|
|
* - `:remote-addr`
|
|
|
|
* - `:date`
|
|
|
|
* - `:method`
|
|
|
|
* - `:url`
|
|
|
|
* - `:referrer`
|
|
|
|
* - `:user-agent`
|
|
|
|
* - `:status`
|
|
|
|
*
|
|
|
|
* @param {String|Function|Object} format or options
|
|
|
|
* @return {Function}
|
|
|
|
* @api public
|
|
|
|
*/
|
|
|
|
|
2013-06-04 06:17:36 +08:00
|
|
|
function getLogger(logger4js, options) {
|
2013-05-11 22:17:23 +08:00
|
|
|
if ('object' == typeof options) {
|
|
|
|
options = options || {};
|
|
|
|
} else if (options) {
|
|
|
|
options = { format: options };
|
|
|
|
} else {
|
|
|
|
options = {};
|
|
|
|
}
|
2011-04-07 08:19:18 +08:00
|
|
|
|
2013-05-11 22:17:23 +08:00
|
|
|
var thislogger = logger4js
|
2013-06-04 06:17:36 +08:00
|
|
|
, level = levels.toLevel(options.level, levels.INFO)
|
|
|
|
, fmt = options.format || DEFAULT_FORMAT
|
|
|
|
, nolog = options.nolog ? createNoLogCondition(options.nolog) : null;
|
2011-04-07 08:19:18 +08:00
|
|
|
|
2013-06-04 06:17:36 +08:00
|
|
|
return function (req, res, next) {
|
|
|
|
// mount safety
|
|
|
|
if (req._logging) return next();
|
2011-04-07 08:19:18 +08:00
|
|
|
|
2013-05-11 22:17:23 +08:00
|
|
|
// nologs
|
|
|
|
if (nolog && nolog.test(req.originalUrl)) return next();
|
|
|
|
if (thislogger.isLevelEnabled(level) || options.level === 'auto') {
|
2015-03-09 03:35:54 +08:00
|
|
|
|
2013-06-04 06:17:36 +08:00
|
|
|
var start = new Date()
|
2013-05-11 22:17:23 +08:00
|
|
|
, statusCode
|
|
|
|
, writeHead = res.writeHead
|
|
|
|
, url = req.originalUrl;
|
|
|
|
|
|
|
|
// flag as logging
|
|
|
|
req._logging = true;
|
2015-03-09 03:35:54 +08:00
|
|
|
|
2013-05-11 22:17:23 +08:00
|
|
|
// proxy for statusCode.
|
|
|
|
res.writeHead = function(code, headers){
|
|
|
|
res.writeHead = writeHead;
|
|
|
|
res.writeHead(code, headers);
|
|
|
|
res.__statusCode = statusCode = code;
|
|
|
|
res.__headers = headers || {};
|
|
|
|
|
|
|
|
//status code response level handling
|
|
|
|
if(options.level === 'auto'){
|
|
|
|
level = levels.INFO;
|
|
|
|
if(code >= 300) level = levels.WARN;
|
|
|
|
if(code >= 400) level = levels.ERROR;
|
|
|
|
} else {
|
2013-06-04 06:17:36 +08:00
|
|
|
level = levels.toLevel(options.level, levels.INFO);
|
2013-05-11 22:17:23 +08:00
|
|
|
}
|
|
|
|
};
|
2015-03-09 03:35:54 +08:00
|
|
|
|
fix bug: headers are changed after log entry emits
In the original version, the following operation looks synchronic, however it is not:
```
res.end = end;
res.end(data,enc);
//emit the log entry
```
In fact, it starts a series of async operations, in which the request may yet be changed after the request log has already been emitted
(in our case - a change on request headers was observed, probably by some low level hook or hacky wrap of some http.ServerResponse method that's involved on the process - but called asynchronously)
what leads to situation that the request log does not capture valid data.
(observed by us:
- request headers
- calculated end time, when concerning big content
)
The fix just used `setTimeout(function() { /*emit the log entry*/ }, 1)`, but I'm afraid it may not hold true for big contents.
Well. maybe the headers part will, but the response time calculation will lie.
The fix relays on: http://nodejs.org/api/http.html#http_event_finish
2014-11-04 23:28:52 +08:00
|
|
|
//hook on end request to emit the log entry of the HTTP request.
|
|
|
|
res.on('finish', function() {
|
2013-06-04 06:17:36 +08:00
|
|
|
res.responseTime = new Date() - start;
|
2014-05-23 18:58:52 +08:00
|
|
|
//status code response level handling
|
|
|
|
if(res.statusCode && options.level === 'auto'){
|
|
|
|
level = levels.INFO;
|
|
|
|
if(res.statusCode >= 300) level = levels.WARN;
|
|
|
|
if(res.statusCode >= 400) level = levels.ERROR;
|
|
|
|
}
|
2013-05-11 22:17:23 +08:00
|
|
|
if (thislogger.isLevelEnabled(level)) {
|
2015-03-10 14:18:02 +08:00
|
|
|
var combined_tokens = assemble_tokens(req, res, options.tokens || []);
|
2013-05-11 22:17:23 +08:00
|
|
|
if (typeof fmt === 'function') {
|
2015-03-10 14:18:02 +08:00
|
|
|
var line = fmt(req, res, function(str){ return format(str, combined_tokens); });
|
2013-05-11 22:17:23 +08:00
|
|
|
if (line) thislogger.log(level, line);
|
|
|
|
} else {
|
2015-03-10 14:18:02 +08:00
|
|
|
thislogger.log(level, format(fmt, combined_tokens));
|
2013-05-11 22:17:23 +08:00
|
|
|
}
|
|
|
|
}
|
fix bug: headers are changed after log entry emits
In the original version, the following operation looks synchronic, however it is not:
```
res.end = end;
res.end(data,enc);
//emit the log entry
```
In fact, it starts a series of async operations, in which the request may yet be changed after the request log has already been emitted
(in our case - a change on request headers was observed, probably by some low level hook or hacky wrap of some http.ServerResponse method that's involved on the process - but called asynchronously)
what leads to situation that the request log does not capture valid data.
(observed by us:
- request headers
- calculated end time, when concerning big content
)
The fix just used `setTimeout(function() { /*emit the log entry*/ }, 1)`, but I'm afraid it may not hold true for big contents.
Well. maybe the headers part will, but the response time calculation will lie.
The fix relays on: http://nodejs.org/api/http.html#http_event_finish
2014-11-04 23:28:52 +08:00
|
|
|
});
|
2011-04-07 08:19:18 +08:00
|
|
|
}
|
2015-03-09 03:35:54 +08:00
|
|
|
|
2013-06-04 06:17:36 +08:00
|
|
|
//ensure next gets always called
|
|
|
|
next();
|
|
|
|
};
|
2011-07-12 11:02:48 +08:00
|
|
|
}
|
2011-04-07 08:19:18 +08:00
|
|
|
|
2015-03-10 14:13:49 +08:00
|
|
|
/**
|
|
|
|
* Adds custom {token, replacement} objects to defaults, overwriting the defaults if any tokens clash
|
|
|
|
*
|
|
|
|
* @param {IncomingMessage} req
|
|
|
|
* @param {ServerResponse} res
|
|
|
|
* @param {Array} custom_tokens [{ token: string-or-regexp, replacement: string-or-replace-function }]
|
|
|
|
* @return {Array}
|
|
|
|
*/
|
2015-03-10 14:18:02 +08:00
|
|
|
function assemble_tokens(req, res, custom_tokens) {
|
|
|
|
var array_unique_tokens = function(array) {
|
|
|
|
var a = array.concat();
|
|
|
|
for(var i=0; i<a.length; ++i) {
|
|
|
|
for(var j=i+1; j<a.length; ++j) {
|
|
|
|
if(a[i].token == a[j].token) { // not === because token can be regexp object
|
|
|
|
a.splice(j--, 1);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
return a;
|
|
|
|
};
|
|
|
|
|
2015-03-10 14:13:49 +08:00
|
|
|
var default_tokens = [];
|
|
|
|
default_tokens.push({ token: ':url', replacement: req.originalUrl });
|
|
|
|
default_tokens.push({ token: ':method', replacement: req.method });
|
|
|
|
default_tokens.push({ token: ':status', replacement: res.__statusCode || res.statusCode });
|
|
|
|
default_tokens.push({ token: ':response-time', replacement: res.responseTime });
|
|
|
|
default_tokens.push({ token: ':date', replacement: new Date().toUTCString() });
|
|
|
|
default_tokens.push({ token: ':referrer', replacement: req.headers.referer || req.headers.referrer || '' });
|
|
|
|
default_tokens.push({ token: ':http-version', replacement: req.httpVersionMajor + '.' + req.httpVersionMinor });
|
|
|
|
default_tokens.push({ token: ':remote-addr', replacement: req.ip || req._remoteAddress ||
|
|
|
|
(req.socket && (req.socket.remoteAddress || (req.socket.socket && req.socket.socket.remoteAddress))) });
|
|
|
|
default_tokens.push({ token: ':user-agent', replacement: req.headers['user-agent'] });
|
|
|
|
default_tokens.push({ token: ':content-length', replacement: (res._headers && res._headers['content-length']) ||
|
|
|
|
(res.__headers && res.__headers['Content-Length']) || '-' });
|
|
|
|
default_tokens.push({ token: /:req\[([^\]]+)\]/g, replacement: function(_, field) {
|
|
|
|
return req.headers[field.toLowerCase()];
|
|
|
|
} });
|
|
|
|
default_tokens.push({ token: /:res\[([^\]]+)\]/g, replacement: function(_, field) {
|
|
|
|
return res._headers ?
|
|
|
|
(res._headers[field.toLowerCase()] || res.__headers[field])
|
|
|
|
: (res.__headers && res.__headers[field]);
|
|
|
|
} });
|
|
|
|
|
2015-03-10 14:18:02 +08:00
|
|
|
return array_unique_tokens(custom_tokens.concat(default_tokens));
|
2015-03-10 14:13:49 +08:00
|
|
|
};
|
|
|
|
|
2011-07-12 11:02:48 +08:00
|
|
|
/**
|
|
|
|
* Return formatted log line.
|
|
|
|
*
|
|
|
|
* @param {String} str
|
|
|
|
* @param {IncomingMessage} req
|
|
|
|
* @param {ServerResponse} res
|
|
|
|
* @return {String}
|
|
|
|
* @api private
|
|
|
|
*/
|
2011-04-07 08:19:18 +08:00
|
|
|
|
2015-03-10 14:13:49 +08:00
|
|
|
function format(str, tokens) {
|
|
|
|
return _.reduce(tokens, function(current_string, token) {
|
|
|
|
return current_string.replace(token.token, token.replacement);
|
|
|
|
}, str);
|
2013-06-04 06:17:36 +08:00
|
|
|
}
|
2011-04-07 08:19:18 +08:00
|
|
|
|
2011-10-25 13:09:41 +08:00
|
|
|
/**
|
|
|
|
* Return RegExp Object about nolog
|
|
|
|
*
|
|
|
|
* @param {String} nolog
|
|
|
|
* @return {RegExp}
|
|
|
|
* @api private
|
2013-06-05 06:37:27 +08:00
|
|
|
*
|
2011-10-25 13:09:41 +08:00
|
|
|
* syntax
|
|
|
|
* 1. String
|
|
|
|
* 1.1 "\\.gif"
|
|
|
|
* NOT LOGGING http://example.com/hoge.gif and http://example.com/hoge.gif?fuga
|
|
|
|
* LOGGING http://example.com/hoge.agif
|
|
|
|
* 1.2 in "\\.gif|\\.jpg$"
|
2015-03-09 03:35:54 +08:00
|
|
|
* NOT LOGGING http://example.com/hoge.gif and
|
2013-06-04 06:17:36 +08:00
|
|
|
* http://example.com/hoge.gif?fuga and http://example.com/hoge.jpg?fuga
|
2015-03-09 03:35:54 +08:00
|
|
|
* LOGGING http://example.com/hoge.agif,
|
2013-06-04 06:17:36 +08:00
|
|
|
* http://example.com/hoge.ajpg and http://example.com/hoge.jpg?hoge
|
2011-10-25 13:09:41 +08:00
|
|
|
* 1.3 in "\\.(gif|jpe?g|png)$"
|
|
|
|
* NOT LOGGING http://example.com/hoge.gif and http://example.com/hoge.jpeg
|
|
|
|
* LOGGING http://example.com/hoge.gif?uid=2 and http://example.com/hoge.jpg?pid=3
|
|
|
|
* 2. RegExp
|
|
|
|
* 2.1 in /\.(gif|jpe?g|png)$/
|
|
|
|
* SAME AS 1.3
|
|
|
|
* 3. Array
|
|
|
|
* 3.1 ["\\.jpg$", "\\.png", "\\.gif"]
|
|
|
|
* SAME AS "\\.jpg|\\.png|\\.gif"
|
|
|
|
*/
|
2013-06-05 06:38:39 +08:00
|
|
|
function createNoLogCondition(nolog) {
|
2013-06-05 06:37:27 +08:00
|
|
|
var regexp = null;
|
|
|
|
|
|
|
|
if (nolog) {
|
|
|
|
if (nolog instanceof RegExp) {
|
|
|
|
regexp = nolog;
|
2015-03-09 03:35:54 +08:00
|
|
|
}
|
|
|
|
|
2013-06-05 06:37:27 +08:00
|
|
|
if (typeof nolog === 'string') {
|
|
|
|
regexp = new RegExp(nolog);
|
2013-06-04 06:17:36 +08:00
|
|
|
}
|
2015-03-09 03:35:54 +08:00
|
|
|
|
2013-06-05 06:37:27 +08:00
|
|
|
if (Array.isArray(nolog)) {
|
|
|
|
var regexpsAsStrings = nolog.map(
|
2015-03-09 03:35:54 +08:00
|
|
|
function convertToStrings(o) {
|
2013-06-05 06:37:27 +08:00
|
|
|
return o.source ? o.source : o;
|
|
|
|
}
|
|
|
|
);
|
|
|
|
regexp = new RegExp(regexpsAsStrings.join('|'));
|
2013-06-04 06:17:36 +08:00
|
|
|
}
|
2013-06-05 06:37:27 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
return regexp;
|
2013-06-04 06:17:36 +08:00
|
|
|
}
|
2011-10-25 13:09:41 +08:00
|
|
|
|
2013-06-04 06:17:36 +08:00
|
|
|
exports.connectLogger = getLogger;
|