diff --git a/README.md b/README.md index f66d381..f9e881d 100644 --- a/README.md +++ b/README.md @@ -31,7 +31,7 @@ Module provides httpResponseCode, and httpResponseTime rules which can be config AuditLogger automatically captures time taken for all middlewares and routes. - req.timer.value - gives time taken for all middleware and routes. -- req.timer.start() and req.timer.stop() - could be used any time during the request to log private functions. +- req.timer.start(name) and req.timer.stop(name) - could be used any time during the request to log private functions. - req.timer.value contains special '$finalTimer' key which contains total time taken for the request. diff --git a/examples/express4.js b/examples/express4.js index 2ecf832..1223ac1 100644 --- a/examples/express4.js +++ b/examples/express4.js @@ -18,10 +18,12 @@ auditLogger(app, { }); app.use(function prkApp1(req, res, next) { + console.log('prkArrrp111'); next(); }); app.use(function prkApp2(req, res, next) { + console.log('omg') setTimeout(function() { middlewarePrivateFunction(req); next(); @@ -40,9 +42,11 @@ router.use(function prkRouterMiddelware1(req, res, next) { //test route which fails 'responseTime' rule router.get('/test', function test(req, res, next) { - privateFunction(req); - privateFunction1(req); - res.status(200).send('Test Page'); + privateFunction(req, function() { + privateFunction1(req); + res.status(200).send('Test Page'); + //next(); + }); }); //test route which fails 'responseCode400s' rule @@ -50,11 +54,12 @@ router.get('/test/httpresponse', function test(req, res, next) { setTimeout(function() { res.status(404).send('404 Page'); }, 0); + next(); }); function middlewarePrivateFunction(req, cb) { req.timers.start('mwPrivateFunction'); - req.timers.stop(); + req.timers.stop('mwPrivateFunction'); } function logData(req, res) { @@ -75,11 +80,12 @@ function privateFunction(req, cb) { req.timers.start('privateFunction'); var t = new Date().getTime(); setTimeout(function() { - req.timers.stop(); - }, 555) + req.timers.stop('privateFunction'); + cb(); + }, 50); } function privateFunction1(req, cb) { req.timers.start('privateFunction1'); - req.timers.stop(); + req.timers.stop('privateFunction1'); } diff --git a/index.js b/index.js index f262c06..decf304 100644 --- a/index.js +++ b/index.js @@ -1,4 +1,4 @@ -var expressSendMethods = ['send', 'json', 'jsonp', 'redirect', 'sendStatus', 'render', 'sendfile', 'sendFile', 'status']; +var expressSendMethods = ['send', 'json', 'jsonp', 'redirect', 'sendStatus', 'render', 'sendfile', 'sendFile']; var httpResponseTime = require('./rules/httpResponseTime'); var httpResponseCode = require('./rules/httpResponseCode'); @@ -17,7 +17,7 @@ function auditLogger(app, rulesObj, notifyCallback) { var tempObj = req.timers.value[i]; var key = Object.keys(tempObj)[0]; var value = tempObj[key]; - if (value === -1) { + if (key.indexOf('->') === -1 && value === -1) { key = key + ' -> ' + name; var timerObj = {}; timerObj[key] = {}; @@ -29,25 +29,25 @@ function auditLogger(app, rulesObj, notifyCallback) { } } - req.timers.stop = function() { + req.timers.stop = function(name) { for (var i = req.timers.value.length - 1; i >= 0; i--) { var tempObj = req.timers.value[i]; var key = Object.keys(tempObj)[0]; + var tempKeyArr = key.split('->'); + var tempKey = tempKeyArr[1] ? tempKeyArr[1].trim() : key; var value = tempObj[key]['init']; - if (value === -1) { - var timerObj = {}; + var timerObj = {}; + if (name && name === tempKey && value === -1) { timerObj[key] = new Date().getTime() - req.timers.value[i][key]['time']; req.timers.value[i] = timerObj; - break; } - } } overrideMethods(res, expressSendMethods, responseSend); function responseSend(responseFn) { return function() { - var args = Array.prototype.slice.call(arguments); + var args = Array.prototype.slice.call(arguments); req.timers.value.push({ '$finalTimer': (new Date().getTime() - startTime) }); @@ -59,9 +59,7 @@ function auditLogger(app, rulesObj, notifyCallback) { if (shouldNotify) { notifyCallback(req, arguments); } - - return responseFn.apply(this, arguments); - } + responseFn.apply(this, arguments); } } next(); }); @@ -121,6 +119,7 @@ function auditLogger(app, rulesObj, notifyCallback) { $obj["timerObj"] = {}; $obj.req = arguments[0]; $obj.counter = new Date().getTime(); + var $name; var nextFn = arguments[2]; if (middlewareFn.name || route) { $obj.name = middlewareFn.name || route; @@ -130,8 +129,13 @@ function auditLogger(app, rulesObj, notifyCallback) { $obj["timerObj"][$obj.name] = -1; $obj.req.timers.value.push($obj["timerObj"]); arguments[2] = function() { - $obj["timerObj"][$obj.name] = new Date().getTime() - $obj.counter; - $obj.req.timers.value.push($obj["timerObj"]); + for (var $i = $obj.req.timers.value.length - 1; $i >= 0; $i--) { + var $key = Object.keys($obj.req.timers.value[$i])[0]; + if ($obj.req.timers.value[$i][$key] === -1) { + $obj.req.timers.value[$i][$key] = new Date().getTime() - $obj.counter; + break; + } + } nextFn.apply(this, arguments); } return middlewareFn.apply(this, arguments); diff --git a/package.json b/package.json index 6315aca..f48e7b5 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "auditlogger", - "version": "0.1.2", + "version": "0.2.0", "description": "logger to control application logging", "main": "index.js", "scripts": {