2013-06-04 06:17:36 +08:00
|
|
|
"use strict";
|
2011-07-12 11:02:48 +08:00
|
|
|
var levels = require("./levels");
|
2013-06-04 06:17:36 +08:00
|
|
|
var DEFAULT_FORMAT = ':remote-addr - -' +
|
|
|
|
' ":method :url HTTP/:http-version"' +
|
|
|
|
' :status :content-length ":referrer"' +
|
|
|
|
' ":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') {
|
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;
|
2013-06-04 06:17:36 +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
|
|
|
}
|
|
|
|
};
|
2013-06-04 06:17:36 +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)) {
|
|
|
|
if (typeof fmt === 'function') {
|
|
|
|
var line = fmt(req, res, function(str){ return format(str, req, res); });
|
|
|
|
if (line) thislogger.log(level, line);
|
|
|
|
} else {
|
|
|
|
thislogger.log(level, format(fmt, req, res));
|
|
|
|
}
|
|
|
|
}
|
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
|
|
|
}
|
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
|
|
|
|
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
|
|
|
|
2013-06-04 06:17:36 +08:00
|
|
|
function format(str, req, res) {
|
2013-05-11 22:17:23 +08:00
|
|
|
return str
|
2013-06-04 06:17:36 +08:00
|
|
|
.replace(':url', req.originalUrl)
|
|
|
|
.replace(':method', req.method)
|
|
|
|
.replace(':status', res.__statusCode || res.statusCode)
|
|
|
|
.replace(':response-time', res.responseTime)
|
|
|
|
.replace(':date', new Date().toUTCString())
|
|
|
|
.replace(':referrer', req.headers.referer || req.headers.referrer || '')
|
|
|
|
.replace(':http-version', req.httpVersionMajor + '.' + req.httpVersionMinor)
|
|
|
|
.replace(
|
2013-12-22 02:42:44 +08:00
|
|
|
':remote-addr', req.ip || req._remoteAddress || (
|
2013-06-04 06:17:36 +08:00
|
|
|
req.socket &&
|
|
|
|
(req.socket.remoteAddress || (req.socket.socket && req.socket.socket.remoteAddress))
|
2013-12-22 02:42:44 +08:00
|
|
|
))
|
2013-06-04 06:17:36 +08:00
|
|
|
.replace(':user-agent', req.headers['user-agent'] || '')
|
|
|
|
.replace(
|
|
|
|
':content-length',
|
|
|
|
(res._headers && res._headers['content-length']) ||
|
|
|
|
(res.__headers && res.__headers['Content-Length']) ||
|
|
|
|
'-'
|
|
|
|
)
|
|
|
|
.replace(/:req\[([^\]]+)\]/g, function(_, field){ return req.headers[field.toLowerCase()]; })
|
|
|
|
.replace(/:res\[([^\]]+)\]/g, function(_, field){
|
|
|
|
return res._headers ?
|
|
|
|
(res._headers[field.toLowerCase()] || res.__headers[field])
|
|
|
|
: (res.__headers && res.__headers[field]);
|
|
|
|
});
|
|
|
|
}
|
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$"
|
2013-06-04 06:17:36 +08:00
|
|
|
* NOT LOGGING http://example.com/hoge.gif and
|
|
|
|
* http://example.com/hoge.gif?fuga and http://example.com/hoge.jpg?fuga
|
|
|
|
* LOGGING http://example.com/hoge.agif,
|
|
|
|
* 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;
|
|
|
|
}
|
|
|
|
|
|
|
|
if (typeof nolog === 'string') {
|
|
|
|
regexp = new RegExp(nolog);
|
2013-06-04 06:17:36 +08:00
|
|
|
}
|
2013-06-05 06:37:27 +08:00
|
|
|
|
|
|
|
if (Array.isArray(nolog)) {
|
|
|
|
var regexpsAsStrings = nolog.map(
|
|
|
|
function convertToStrings(o) {
|
|
|
|
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;
|