From 0be988823458374d88f42421cdb9bfa4ff0db44c Mon Sep 17 00:00:00 2001 From: Son Tran-Nguyen Date: Tue, 14 Jul 2015 09:48:21 +0700 Subject: [PATCH 1/6] Switch from Winston to Bunyan for logging --- lib/logging.js | 55 +++++++++++++++++++++++++------------------------- package.json | 4 ++-- 2 files changed, 30 insertions(+), 29 deletions(-) diff --git a/lib/logging.js b/lib/logging.js index a5c821b..d7631f8 100644 --- a/lib/logging.js +++ b/lib/logging.js @@ -15,10 +15,9 @@ */ var - winston = require('winston') + bunyan = require('bunyan') ; - // The default logging levels seem to be changing a lot so let's just set our own var loggingLevels = { levels: { input: 0, verbose: 1, debug: 2, info: 3, event: 4, warn: 5, error: 6 }, @@ -26,34 +25,36 @@ var loggingLevels = { }; /* - Configure Winston logging + Configure Bunyan logging */ -var logger = new (winston.Logger)({ - levels: loggingLevels.levels, - colors: loggingLevels.colors, - transports: [] -}); +var streams = []; -// If we are running as a service then output to DailyRotateFile if (GLOBAL.config.args.spawned) { - logger.add(winston.transports.DailyRotateFile, { - timestamp: true, - filename: process.cwd() + '/logs/spasout.log', - datePattern: '.yyyy-MM-dd', - level: GLOBAL.config.args.log, - handleExceptions: true, - exitOnError: false - }); -// otherwise output straight to the console + // If we are running as a service then output to DailyRotateFile + streams.push({ + type: 'rotating-file', + path: process.cwd() + '/logs/spasout.log', + period: '1d', // daily rotation + count: 3, // keep 3 back copies + level: GLOBAL.config.args.log + }); + } else { - logger.add(winston.transports.Console, { - timestamp: false, - colorize: true, - level: GLOBAL.config.args.log, - handleExceptions: true, - exitOnError: false, - json: false - }); + // otherwise output straight to the console + streams.push({ + type: 'stream', + stream: process.stdout, + level: GLOBAL.config.args.log + }); } -exports.winston = logger; \ No newline at end of file +var logger = bunyan.createLogger({ + name: 'SPAS', + streams: streams +}); + +// Backward compatibility +logger.event = logger.debug; +exports.winston = logger; + +exports.log = logger; \ No newline at end of file diff --git a/package.json b/package.json index 7dea9db..b7e5e7d 100644 --- a/package.json +++ b/package.json @@ -27,6 +27,7 @@ "spas": "./bin/spas" }, "dependencies": { + "bunyan": "^1.4.0", "connect": "2.8.5", "cron": "1.0.1", "date-utils": "1.2.14", @@ -42,8 +43,7 @@ "request": "2.27.0", "spas-http": "0.1.6", "underscore": "1.5.1", - "watch": "0.8.0", - "winston": "0.7.2" + "watch": "0.8.0" }, "devDependencies": { "vows": "0.7.0" From 8b08d9581f80172c69f836e9496e5bd978e05594 Mon Sep 17 00:00:00 2001 From: Son Tran-Nguyen Date: Tue, 14 Jul 2015 11:21:48 +0700 Subject: [PATCH 2/6] Ensure valid log level config - Custom levels (`event`, `verbose`) are aliased. - Add tests for logging levels using vows. - Add npm scripts: `npm start` and `npm test` --- lib/logging.js | 25 +++++++++++++++++--- package.json | 4 ++++ test/logging.js | 63 +++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 89 insertions(+), 3 deletions(-) create mode 100644 test/logging.js diff --git a/lib/logging.js b/lib/logging.js index d7631f8..223e990 100644 --- a/lib/logging.js +++ b/lib/logging.js @@ -27,7 +27,26 @@ var loggingLevels = { /* Configure Bunyan logging */ -var streams = []; +var streams = [], level = GLOBAL.config.args.log; +switch (level) { + case "error": + case "warn": + case "info": + case "debug": + break; + case "event": + level = "info"; + break; + case "verbose": + level = "debug"; + break; + case "data": + // @TODO: Which level do we set to? + break; + case "input": + // @TODO: Which level do we set to? + break; +} if (GLOBAL.config.args.spawned) { // If we are running as a service then output to DailyRotateFile @@ -36,7 +55,7 @@ if (GLOBAL.config.args.spawned) { path: process.cwd() + '/logs/spasout.log', period: '1d', // daily rotation count: 3, // keep 3 back copies - level: GLOBAL.config.args.log + level: level }); } else { @@ -44,7 +63,7 @@ if (GLOBAL.config.args.spawned) { streams.push({ type: 'stream', stream: process.stdout, - level: GLOBAL.config.args.log + level: level }); } diff --git a/package.json b/package.json index b7e5e7d..da2f7b0 100644 --- a/package.json +++ b/package.json @@ -26,6 +26,10 @@ "bin": { "spas": "./bin/spas" }, + "scripts": { + "start" : "node spas", + "test": "./node_modules/vows/bin/vows ./test/*.js" + }, "dependencies": { "bunyan": "^1.4.0", "connect": "2.8.5", diff --git a/test/logging.js b/test/logging.js new file mode 100644 index 0000000..451fdc4 --- /dev/null +++ b/test/logging.js @@ -0,0 +1,63 @@ +var LEVELS = { + FATAL: 60, + ERROR: 50, + WARN: 40, + INFO: 30, + DEBUG: 20, + TRACE: 10 +}; + +var vows = require('vows'), + assert = require('assert'); + +// Macro to initialize the logger topic. +function init(level) { + GLOBAL.config = { args: { log: level.toLowerCase() } }; + var logger = require('../lib/logging.js').log; + // Need to delete require cache so we could require it again in next tests + delete require.cache[require.resolve('../lib/logging.js')]; + return logger; +} +// Macro to assert the logger's level. +function assertLevel(level) { + return function(logger) { + assert.equal(logger.level(), level); + }; +} +// Macro to return a test context for a logging level. +function ensureLevel(actual, expected) { + if (!expected) { expected = actual; } + var context = { + topic: init(actual) + }; + context['gets ' + expected] = assertLevel(LEVELS[expected]); + return context; +} + +exports.levelsTestSuite = vows +.describe('Setting log level to') +// Run each text in batch to ensure sequential operations. +.addBatch({ + 'FATAL': ensureLevel('FATAL') +}) +.addBatch({ + 'ERROR': ensureLevel('ERROR') +}) +.addBatch({ + 'WARN': ensureLevel('WARN') +}) +.addBatch({ + 'INFO': ensureLevel('INFO') +}) +.addBatch({ + 'DEBUG': ensureLevel('DEBUG') +}) +.addBatch({ + 'TRACE': ensureLevel('TRACE') +}) +.addBatch({ + 'EVENT': ensureLevel('EVENT', 'INFO') +}) +.addBatch({ + 'VERBOSE': ensureLevel('VERBOSE', 'DEBUG') +}); \ No newline at end of file From 672efff1a27dc7b3c154f2b0dd1c4a9a3b191127 Mon Sep 17 00:00:00 2001 From: Son Tran-Nguyen Date: Tue, 14 Jul 2015 22:31:13 +0700 Subject: [PATCH 3/6] Remove all references to winston --- lib/bundleManager.js | 16 ++++++++-------- lib/engine.js | 32 ++++++++++++++++---------------- lib/keystone2.js | 38 +++++++++++++++++++------------------- lib/logging.js | 7 ------- lib/oauth.js | 20 ++++++++++---------- lib/oauth2.js | 36 ++++++++++++++++++------------------ lib/streaming.js | 4 ++-- spas.js | 14 +++++++------- 8 files changed, 80 insertions(+), 87 deletions(-) diff --git a/lib/bundleManager.js b/lib/bundleManager.js index f500744..7a444cc 100644 --- a/lib/bundleManager.js +++ b/lib/bundleManager.js @@ -1,7 +1,7 @@ var EventEmitter = require('events').EventEmitter , fs = require('fs') , _ = require('underscore') - , winston = require('./logging').winston + , log = require('./logging').log , engine = require('./engine') , util = require('util') , watch = require('watch') @@ -44,7 +44,7 @@ var BundleManager = function() { // Either this is the first load or a bundle has been added, deleted or changed this.refreshBundles = function( targetFile, callback ) { - winston.info('bundleManager refreshBundles'); + log.info('bundleManager refreshBundles'); var bundles = {} , files = fs.readdirSync(bundlesFolder); @@ -57,12 +57,12 @@ var BundleManager = function() { try { var tempBundle = require(bundlesFolder + "/" + file); _.each(tempBundle, function(part, key) { - winston.info("Bundle \""+key+"\": loaded from \"" + file + "\""); + log.info("Bundle \""+key+"\": loaded from \"" + file + "\""); bundles[key] = part; bundles[key].locked = false; }); } catch(err) { - winston.error("Error parsing bundle \""+file+"\": "+err); + log.error("Error parsing bundle \""+file+"\": "+err); } } @@ -82,7 +82,7 @@ var BundleManager = function() { _.each(bundle, function (api, key) { if (api.schedule) { var job = new cronJob(api.schedule, function(){ - winston.info('cronjob '+key+' called'); + log.info('cronjob '+key+' called'); engine.refresh(api, key, bid, bundle); }, null, true); GLOBAL.cronjobs.push(job); @@ -99,14 +99,14 @@ var BundleManager = function() { monitor.on("created", function (file, stat) { if ( file.endsWith('.js') ) { - winston.event('Bundle file created: ' + file); + log.event('Bundle file created: ' + file); self.refreshBundles(); } }); monitor.on("changed", function (file, curr, prev) { if ( file.endsWith('.js') ) { - winston.event('Bundle file changed: ' + file); + log.event('Bundle file changed: ' + file); // To bust node's module caching we rename the file before calling updateBundle var tempFile = '.'+uuid.v4(); @@ -120,7 +120,7 @@ var BundleManager = function() { monitor.on("removed", function (file, stat) { if ( file.endsWith('.js') ) { - winston.event('Bundle file removed: ' + file); + log.event('Bundle file removed: ' + file); self.refreshBundles(); } }); diff --git a/lib/engine.js b/lib/engine.js index 2c378fa..fe2e1dd 100644 --- a/lib/engine.js +++ b/lib/engine.js @@ -3,7 +3,7 @@ var , _ = require('underscore')._ , neuron = require('neuron') , zlib = require('zlib') - , winston = require('./logging').winston + , log = require('./logging').log , oauth = require("./oauth") , oauth2 = require('./oauth2') ; @@ -103,7 +103,7 @@ var sendResponse = function(jDoc, myRes, ip, bid, callback, gzip) { responseHeaders['content-encoding'] = 'gzip'; zlib.gzip(doc, function(err, zbuf) { if (!err) { - winston.event('Send gzipped response for ' + bid +', ' + zbuf.toString().length + ', ' + ip); + log.event('Send gzipped response for ' + bid +', ' + zbuf.toString().length + ', ' + ip); myRes.writeHead(200, responseHeaders); myRes.end(zbuf); } @@ -112,7 +112,7 @@ var sendResponse = function(jDoc, myRes, ip, bid, callback, gzip) { // If a callback name was passed, use it. Otherwise, just output the object var tbuf = new Buffer(doc); myRes.writeHead(200, responseHeaders); - winston.event('Send response for ' + bid +', ' + doc.length + ', ' + ip); + log.event('Send response for ' + bid +', ' + doc.length + ', ' + ip); myRes.end(tbuf); } @@ -125,7 +125,7 @@ var sendResponse = function(jDoc, myRes, ip, bid, callback, gzip) { // exports.refresh = function(api, key, bid, bundle) { - winston.info('exports.refresh: ' + api); + log.info('exports.refresh: ' + api); // We're forcing a refresh of the content so run the api.code api.resource( api.params, api.credentials, function( err, res ) { if ( err ) { @@ -144,7 +144,7 @@ exports.refresh = function(api, key, bid, bundle) { } else { - winston.event('Get data for ' + bid + ' from ' + key + ', ' + res.size); + log.event('Get data for ' + bid + ' from ' + key + ', ' + res.size); // Perform cleanup function on API response if (_.has(api, 'cleanup')) { @@ -184,7 +184,7 @@ exports.refresh = function(api, key, bid, bundle) { // exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { - winston.info('exports.fulfill: ' + bid); + log.info('exports.fulfill: ' + bid); var bundle = GLOBAL.bundles[bid], now = new Date(); @@ -235,7 +235,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { // There was an error so force refresh on bundle exports.fulfill( myRes, ip, bid, callback, gzip, true ); } else { - winston.debug('bid'+bid+':' + doc); + log.debug('bid'+bid+':' + doc); jDoc = JSON.parse( doc ); GLOBAL.bundles[bid].expiration = new Date(jDoc.expires); jDoc.fromcache = true; @@ -251,7 +251,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.addJob('fulfillPart', { work: function(api, bid, key, override, cachedPart) { - winston.info('manager:fulfillPart: ' + bid + '.' + key + ', override: '+override); + log.info('manager:fulfillPart: ' + bid + '.' + key + ', override: '+override); var self = this; @@ -284,7 +284,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { if (_.has( api, 'auth')) { - winston.info('Bundle uses auth type ' + api.auth.type); + log.info('Bundle uses auth type ' + api.auth.type); // If the API request object has an auth scheme defined if (api.auth.type == 'oauth') { oauth.authorize (api, bid, key, function( result, authParams ) { @@ -307,7 +307,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { self.finished = true; }); } else { - winston.error('auth type ' + api.auth.type + ' not recognized'); + log.error('auth type ' + api.auth.type + ' not recognized'); //Could potentially perma lock here if all APIs have bad types } } else { @@ -324,7 +324,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.addJob('startRequest', { work: function( api, key, cachedPart, bid ) { - winston.info('manager:startRequest: ' + key); + log.info('manager:startRequest: ' + key); var self = this; @@ -358,11 +358,11 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { tout.result = _.isUndefined(cachedPart) ? {} : cachedPart; tout.fromcache = true; tout.err = err; - winston.error('Problem retrieving data for ' + bid + ' from ' + key + ': ' + JSON.stringify(err)); + log.error('Problem retrieving data for ' + bid + ' from ' + key + ': ' + JSON.stringify(err)); } else { - winston.event('Get data for ' + bid + ' from ' + key + ', ' + res.size); + log.event('Get data for ' + bid + ' from ' + key + ', ' + res.size); // Perform cleanup function on API response if (_.has(api, 'cleanup')) { @@ -397,7 +397,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.addJob('finishRequest', { work: function(apiResponse) { - winston.info('manager:finishRequest'); + log.info('manager:finishRequest'); queriesInThisBundle--; @@ -419,7 +419,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.addJob('composeResponse', { work: function() { - winston.info('manager:composeResponse'); + log.info('manager:composeResponse'); // Update the expiration date on the bundle var tout = { @@ -463,7 +463,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.addJob('sendResponse', { work: function(doc) { - winston.info('manager:sendResponse'); + log.info('manager:sendResponse'); if (_.has(doc, 'redirect')) { diff --git a/lib/keystone2.js b/lib/keystone2.js index a61f762..60ee89b 100644 --- a/lib/keystone2.js +++ b/lib/keystone2.js @@ -26,7 +26,7 @@ manager.on('empty', function (job) { /* manager.addJob('getCode', { work: function( api, bid, key, cb ) { - winston.verbose('--- getCode --- '); + log.verbose('--- getCode --- '); var oaData = config.authentication[api.auth.provider]; var self = this; var tout = { @@ -48,10 +48,10 @@ manager.addJob('getCode', { /* manager.addJob('getTokens', { work: function( api, bid, key, cb ) { - winston.verbose('--- getTokens ---'); + log.verbose('--- getTokens ---'); var oaData = config.authentication[api.auth.provider], self = this; - winston.verbose('code='+api.credentials.code+ + log.verbose('code='+api.credentials.code+ '&client_id='+oaData.client_id+ '&client_secret='+oaData.client_secret+ '&redirect_uri='+config.url + "/auth" + @@ -68,13 +68,13 @@ manager.addJob('getTokens', { '&grant_type=authorization_code' }, function (err, myres, body) { - winston.verbose('getTokens response', body); + log.verbose('getTokens response', body); var jsRes = JSON.parse(body); api.credentials.access_token = jsRes.access_token; api.credentials.refresh_token = jsRes.refresh_token; api.credentials.expires = new Date().add({seconds: jsRes.expires_in}); - winston.verbose('SET', bid+key+'oauth2', JSON.stringify(api.credentials)); + log.verbose('SET', bid+key+'oauth2', JSON.stringify(api.credentials)); client.set(bid+key+'oauth2', JSON.stringify(api.credentials)); @@ -88,13 +88,13 @@ manager.addJob('getTokens', { /* manager.addJob('refreshTokens', { work: function( api, bid, key, cb ) { - winston.verbose('--- refreshTokens ---'); - winston.verbose('api', api); + log.verbose('--- refreshTokens ---'); + log.verbose('api', api); var oaData = config.authentication[api.auth.provider], self = this; - winston.verbose(oaData.oauth2token); - winston.verbose('client_id='+oaData.client_id+ + log.verbose(oaData.oauth2token); + log.verbose('client_id='+oaData.client_id+ '&client_secret='+oaData.client_secret+ '&refresh_token='+api.credentials.refresh_token + '&grant_type=refresh_token'); @@ -109,13 +109,13 @@ manager.addJob('refreshTokens', { '&grant_type=refresh_token' }, function (err, myres, body) { - winston.verbose('refreshTokens response', body); + log.verbose('refreshTokens response', body); var jsRes = JSON.parse(body); api.credentials.access_token = jsRes.access_token; api.credentials.expires = new Date().add({seconds: jsRes.expires_in}); - winston.verbose('SET', bid+key+'oauth2', JSON.stringify(api.credentials)); + log.verbose('SET', bid+key+'oauth2', JSON.stringify(api.credentials)); client.set(bid+key+'oauth2', JSON.stringify(api.credentials)); @@ -132,16 +132,16 @@ manager.addJob('refreshTokens', { /* manager.addJob('finishAuth', { work: function( tout, cb ) { - winston.verbose('--- finishAuth ---'); + log.verbose('--- finishAuth ---'); cb(tout); } }); */ /* exports.saveCode = function( res, state, code) { - winston.verbose('--- saveCode ---'); + log.verbose('--- saveCode ---'); var doc = {"code": code }; - winston.verbose('SET', state[0]+state[1]+'oauth2', JSON.stringify(doc)); + log.verbose('SET', state[0]+state[1]+'oauth2', JSON.stringify(doc)); client.set(state[0]+state[1]+'oauth2', JSON.stringify(doc)); res.end(""); @@ -149,26 +149,26 @@ exports.saveCode = function( res, state, code) { */ /* exports.revoke = function( res, creds ) { - winston.verbose('--- revoke ---'); + log.verbose('--- revoke ---'); client.del(creds+'oauth2'); res.end("

Credentials revoked

"); } */ /* exports.authorize = function( api, bid, key, cb ) { - winston.verbose('--- authorize ---'); + log.verbose('--- authorize ---'); // See if we have an oauth2 record in the database client.get(bid+key+'oauth2', function (err, doc) { if (err || doc === null) { manager.enqueue('getCode', api, bid, key, cb); } else { - winston.verbose(bid+key+'oauth2', doc); + log.verbose(bid+key+'oauth2', doc); api.credentials = JSON.parse(doc); api.credentials.expires = new Date(api.credentials.expires); if (_.has(api.credentials, 'access_token')) { - winston.verbose('has access_token'); + log.verbose('has access_token'); if (api.credentials.expires.isBefore(new Date())) { - winston.verbose('It has expired. Calling refreshTokens'); + log.verbose('It has expired. Calling refreshTokens'); manager.enqueue('refreshTokens', api, bid, key, cb); } else { manager.enqueue('finishAuth', true, cb); diff --git a/lib/logging.js b/lib/logging.js index 223e990..0cd4dd7 100644 --- a/lib/logging.js +++ b/lib/logging.js @@ -17,12 +17,6 @@ var bunyan = require('bunyan') ; - -// The default logging levels seem to be changing a lot so let's just set our own -var loggingLevels = { - levels: { input: 0, verbose: 1, debug: 2, info: 3, event: 4, warn: 5, error: 6 }, - colors: { input: 'cyan', verbose: 'blue', debug: 'grey', info: 'green', event: 'white', warn: 'yellow', error: 'red' } -}; /* Configure Bunyan logging @@ -74,6 +68,5 @@ var logger = bunyan.createLogger({ // Backward compatibility logger.event = logger.debug; -exports.winston = logger; exports.log = logger; \ No newline at end of file diff --git a/lib/oauth.js b/lib/oauth.js index b3759e1..4de6efc 100644 --- a/lib/oauth.js +++ b/lib/oauth.js @@ -1,7 +1,7 @@ var redis = require("redis") , _ = require('underscore')._ , neuron = require('neuron') - , winston = require('./logging').winston + , log = require('./logging').log , oauth = require('oauth').OAuth , uuid = require("node-uuid") ; @@ -32,7 +32,7 @@ manager.addJob('finishAuth', { manager.addJob('getTemporaryCredentials', { work: function( api, bid, key, cb ) { - winston.info ('getTemporaryCredentials called for ' + bid + ', ' + key); + log.info ('getTemporaryCredentials called for ' + bid + ', ' + key); var oaData = GLOBAL.config.authentication[api.auth.provider]; var oa = new oauth(oaData.requestTemporaryCredentials, @@ -46,7 +46,7 @@ manager.addJob('getTemporaryCredentials', { oa.getOAuthRequestToken(function(error, oauth_token, oauth_token_secret, results){ if(error) { - winston.error(error); + log.error(error); manager.enqueue('finishAuth', error, cb); self.finished = true; } else { @@ -64,7 +64,7 @@ manager.addJob('getTemporaryCredentials', { cname: key, guid: uuid.v4() }; - winston.debug('Authorize redirect response:' + JSON.stringify(tout)); + log.debug('Authorize redirect response:' + JSON.stringify(tout)); manager.enqueue('finishAuth', tout, cb); self.finished = true; } @@ -75,7 +75,7 @@ manager.addJob('getTemporaryCredentials', { manager.addJob('getAccessToken', { work: function(api, bid, key, oauth_token, oauth_verifier, cb) { - winston.info('Running getAccessToken for ' + bid + ', ' + key); + log.info('Running getAccessToken for ' + bid + ', ' + key); var oaData = GLOBAL.config.authentication[api.auth.provider], self = this; @@ -87,13 +87,13 @@ manager.addJob('getAccessToken', { oaData.authorize_callback, oaData.encryption); - winston.debug('oauth_token:' + oauth_token + ' api.credentials.oauth_token_secret:' + api.credentials.oauth_token_secret); + log.debug('oauth_token:' + oauth_token + ' api.credentials.oauth_token_secret:' + api.credentials.oauth_token_secret); oa.getOAuthAccessToken(oauth_token, api.credentials.oauth_token_secret, oauth_verifier, function(error, oauth_access_token, oauth_access_token_secret, results2) { if(error) { // handle error - winston.error(error); + log.error(error); manager.enqueue('finishAuth', error, cb); self.finished = true; } else { @@ -124,10 +124,10 @@ manager.addJob('getAccessToken', { exports.authorize = function( api, bid, key, cb ) { - winston.info('oauth authorize called for ' + bid +', ' + key); + log.info('oauth authorize called for ' + bid +', ' + key); if (!_.has(GLOBAL.config, 'authentication') || !_.has(GLOBAL.config.authentication, api.auth.provider)) { - winston.error('Authentication provider ' + api.auth.provider + ' not defined'); + log.error('Authentication provider ' + api.auth.provider + ' not defined'); return false; } @@ -163,7 +163,7 @@ exports.authorize = function( api, bid, key, cb ) { exports.saveOauthToken = function( api, oauth_token, oauth_verifier, bid, key, cb) { - winston.info('Running saveOauthToken for ' + bid + ', ' + key); + log.info('Running saveOauthToken for ' + bid + ', ' + key); client.get(bid+key+'oauth', function(err, doc) { diff --git a/lib/oauth2.js b/lib/oauth2.js index 37e2ec7..c5b9dc4 100644 --- a/lib/oauth2.js +++ b/lib/oauth2.js @@ -1,7 +1,7 @@ var redis = require("redis") , _ = require('underscore')._ , neuron = require('neuron') - , winston = require('./logging').winston + , log = require('./logging').log , oauth2 = require('oauth').OAuth2 ; @@ -23,7 +23,7 @@ var manager = new neuron.JobManager(); manager.addJob('finishAuth', { work: function( tout, cb, authParams ) { - winston.info('Run job oauth2:finishAuth'); + log.info('Run job oauth2:finishAuth'); cb(tout, authParams); } }); @@ -31,7 +31,7 @@ manager.addJob('finishAuth', { manager.addJob('getCode', { work: function( api, bid, key, cb ) { - winston.info('Run job oauth2:getCode'); + log.info('Run job oauth2:getCode'); var oaData = GLOBAL.config.authentication[api.auth.provider]; @@ -56,7 +56,7 @@ manager.addJob('getCode', { cname: key }; - winston.debug(JSON.stringify(tout)); + log.debug(JSON.stringify(tout)); manager.enqueue('finishAuth', tout, cb); self.finished = true; @@ -66,7 +66,7 @@ manager.addJob('getCode', { manager.addJob('getAccessToken', { work: function(api, bid, key, cb, grant_type) { - winston.info('Run job oauth2:getAccessToken(' + grant_type + ')'); + log.info('Run job oauth2:getAccessToken(' + grant_type + ')'); var oaData = GLOBAL.config.authentication[api.auth.provider], self = this; var oa = new oauth2(oaData.client_id, @@ -76,8 +76,8 @@ manager.addJob('getAccessToken', { oaData.accessTokenPath), self = this; - winston.debug('api = ' + JSON.stringify(api)); - winston.info('oaData = ' + JSON.stringify(oaData)); + log.debug('api = ' + JSON.stringify(api)); + log.info('oaData = ' + JSON.stringify(oaData)); //oa.setAccessTokenName(api.credentials.access_token); var params = { @@ -92,13 +92,13 @@ manager.addJob('getAccessToken', { thisCode = api.credentials.refresh_token; } - winston.info('thisCode = ' + thisCode); - winston.info('params = ' + JSON.stringify(params)); + log.info('thisCode = ' + thisCode); + log.info('params = ' + JSON.stringify(params)); oa.getOAuthAccessToken(thisCode, params, function(error, access_token, refresh_token, results) { - winston.info('Run callback for oauth2:getOAuthAccessToken'); + log.info('Run callback for oauth2:getOAuthAccessToken'); if(error) { - winston.error('Error oauth2:getOAuthAccessToken('+bid+key+'): '+JSON.stringify(error)); + log.error('Error oauth2:getOAuthAccessToken('+bid+key+'): '+JSON.stringify(error)); var tout = { expires: new Date(), err: error, @@ -107,24 +107,24 @@ manager.addJob('getAccessToken', { manager.enqueue('finishAuth', tout, cb); self.finsihed = true; } else { - winston.debug('access_token = '+access_token); + log.debug('access_token = '+access_token); api.credentials.type = 'oauth2'; api.credentials.provider = api.auth.provider; api.credentials.access_token = access_token; - winston.debug('typeof refresh_token = '+typeof refresh_token); + log.debug('typeof refresh_token = '+typeof refresh_token); if (typeof refresh_token !== 'undefined') { - winston.debug('first refresh token = '+refresh_token); + log.debug('first refresh token = '+refresh_token); api.credentials.refresh_token = refresh_token; } api.credentials.expires = new Date().add({seconds: (results.expires_in - 300)}); - winston.debug(JSON.stringify(api.credentials)); + log.debug(JSON.stringify(api.credentials)); client.set(bid+key+'oauth2', JSON.stringify(api.credentials)); - winston.debug(bid+key+'oauth2 saved'); + log.debug(bid+key+'oauth2 saved'); manager.enqueue('finishAuth', true, cb, { "access_token": api.credentials.access_token }); self.finished = true; } @@ -134,7 +134,7 @@ manager.addJob('getAccessToken', { exports.authorize = function( api, bid, key, cb ) { - winston.info('function oauth2:authorize'); + log.info('function oauth2:authorize'); // See if we have an oauth record in the database client.get(bid+key+'oauth2', function (err, doc) { @@ -164,7 +164,7 @@ exports.authorize = function( api, bid, key, cb ) { exports.saveCode = function( res, state, code, cb) { - winston.info('function oauth2:saveCode'); + log.info('function oauth2:saveCode'); var doc = {"code": code }; client.set(state[0]+state[1]+'oauth2', JSON.stringify(doc)); diff --git a/lib/streaming.js b/lib/streaming.js index 7c48166..0cd81d4 100644 --- a/lib/streaming.js +++ b/lib/streaming.js @@ -1,7 +1,7 @@ var redis = require("redis") , redisRStream = require('redis-rstream') , zlib = require('zlib') - , winston = require('./logging').winston + , log = require('./logging').log ; // Connect to redis @@ -19,7 +19,7 @@ if (GLOBAL.config.redis.auth) { // exports.response = function( bid, gzip, myRes, callback ) { - winston.info('streaming.response: ' + bid); + log.info('streaming.response: ' + bid); var responseType = callback ? 'application/javascript' : 'application/json'; diff --git a/spas.js b/spas.js index 45c11ab..d23d106 100644 --- a/spas.js +++ b/spas.js @@ -40,7 +40,7 @@ GLOBAL.config = {}; var // My lib files configure = require('./lib/config'), - winston = require('./lib/logging').winston, + log = require('./lib/logging').log, bundleManager = require('./lib/bundleManager'), engine = require('./lib/engine'), oauth = require('./lib/oauth'), @@ -109,8 +109,8 @@ if (GLOBAL.config.args.service) { get: function() { var oauth_token = querystring.parse((url.parse(this.req.url).query)).oauth_token; - //winston.info('oauth callback for ' + nonce + ' running'); - winston.debug('Query parameters:' + JSON.stringify(querystring.parse((url.parse(this.req.url).query)))); + //log.info('oauth callback for ' + nonce + ' running'); + log.debug('Query parameters:' + JSON.stringify(querystring.parse((url.parse(this.req.url).query)))); if (!_.isUndefined(oauth_token) && !_.isUndefined(this.req.headers.cookie)) { @@ -152,8 +152,8 @@ if (GLOBAL.config.args.service) { get: function() { var self = this; - winston.info('oauth2 callback reqeusted'); - winston.debug(JSON.stringify(querystring.parse((url.parse(this.req.url).query)))); + log.info('oauth2 callback reqeusted'); + log.debug(JSON.stringify(querystring.parse((url.parse(this.req.url).query)))); oauth2.saveCode ( this.res, querystring.parse((url.parse(this.req.url).query)).state.split(','), querystring.parse((url.parse(this.req.url).query)).code, function( tout ) { if (_.has(tout, 'redirect')) { @@ -169,7 +169,7 @@ if (GLOBAL.config.args.service) { '/bundle/:bid': { get: function(bid) { var gzip = acceptGZip(this.req.headers); - winston.error('Old style bundle request made for ' + bid); + log.error('Old style bundle request made for ' + bid); engine.fulfill ( this.res, this.req.headers['x-forwarded-for'] || this.req.connection.remoteAddress, bid, querystring.parse((url.parse(this.req.url).query)).callback, gzip ); } }, @@ -209,5 +209,5 @@ if (GLOBAL.config.args.service) { bundler.refreshBundles(); server.listen(GLOBAL.config.port); - winston.info('Listening on port ' + GLOBAL.config.port); + log.info('Listening on port ' + GLOBAL.config.port); } From 18fe4c4dc38ff743ad013acc827369c96fa748db Mon Sep 17 00:00:00 2001 From: Son Tran-Nguyen Date: Wed, 15 Jul 2015 11:32:25 +0700 Subject: [PATCH 4/6] Add event log to prototype instead of function Add Bunyan's `Logger.prototype.event` instead of `event` function on the logger instance. --- lib/logging.js | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/lib/logging.js b/lib/logging.js index 0cd4dd7..04807de 100644 --- a/lib/logging.js +++ b/lib/logging.js @@ -15,7 +15,7 @@ */ var - bunyan = require('bunyan') + Logger = require('bunyan') ; /* @@ -61,12 +61,16 @@ if (GLOBAL.config.args.spawned) { }); } -var logger = bunyan.createLogger({ +var logger = Logger.createLogger({ name: 'SPAS', streams: streams }); +Logger.prototype.event = function() { + this.debug.apply(this, arguments); +}; + // Backward compatibility -logger.event = logger.debug; +//logger.event = logger.debug; exports.log = logger; \ No newline at end of file From a5a9fbdad0c6fa4bab4e3bc1ac4b3a7828ae3978 Mon Sep 17 00:00:00 2001 From: Son Tran-Nguyen Date: Wed, 15 Jul 2015 11:34:22 +0700 Subject: [PATCH 5/6] Using child loggers to have more fields Child loggers can contain `bid`, `key`, `ip`, `override` fields so that any log calls will include them. This can help when aggregating logs. --- lib/engine.js | 64 +++++++++++++++++++++++++++++---------------------- lib/oauth.js | 36 +++++++++++++++++------------ lib/oauth2.js | 44 ++++++++++++++++++++--------------- 3 files changed, 82 insertions(+), 62 deletions(-) diff --git a/lib/engine.js b/lib/engine.js index fe2e1dd..87853d8 100644 --- a/lib/engine.js +++ b/lib/engine.js @@ -3,7 +3,7 @@ var , _ = require('underscore')._ , neuron = require('neuron') , zlib = require('zlib') - , log = require('./logging').log + , logger = require('./logging').log , oauth = require("./oauth") , oauth2 = require('./oauth2') ; @@ -42,6 +42,7 @@ var filter = function( source, map) { // ## Function to send the response to the user // var sendResponse = function(jDoc, myRes, ip, bid, callback, gzip) { + var log = logger.child({bid: bid, ip: ip}); // Convert the string representation of date to a Date object jDoc.expires = new Date(jDoc.expires); @@ -118,29 +119,30 @@ var sendResponse = function(jDoc, myRes, ip, bid, callback, gzip) { } -} +}; // // ## Perform scheduled refresh // exports.refresh = function(api, key, bid, bundle) { + var log = logger.child({bid: bid, key: key}); - log.info('exports.refresh: ' + api); + log.info('exports.refresh: ' + bid + ' ' + key); // We're forcing a refresh of the content so run the api.code api.resource( api.params, api.credentials, function( err, res ) { if ( err ) { // We got an error so set our output object to be the error and expire immediately api.expires = ( new Date() ); - var tout = { - expires: api.expires, - result: err, - iid: bid+key, - cname: key, - scheduled: true - }; + var tout = { + expires: api.expires, + result: err, + iid: bid+key, + cname: key, + scheduled: true + }; - // Why are we doing this? Nothing happens here. + // Why are we doing this? Nothing happens here. } else { @@ -161,11 +163,11 @@ exports.refresh = function(api, key, bid, bundle) { bundle[key] = api; var tout = { - expires: api.expires, - result: res, - iid: api.iid, - cname: key, - scheduled: true + expires: api.expires, + result: res, + iid: api.iid, + cname: key, + scheduled: true }; // Save the API response to Redis @@ -183,6 +185,7 @@ exports.refresh = function(api, key, bid, bundle) { // ## Retrieve the requested bundle // exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { + var log = logger.child({bid: bid, ip: ip, override: override}); log.info('exports.fulfill: ' + bid); @@ -250,6 +253,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.addJob('fulfillPart', { work: function(api, bid, key, override, cachedPart) { + var log = logger.child({bid: bid, key: key, override: override, ip: ip}); log.info('manager:fulfillPart: ' + bid + '.' + key + ', override: '+override); @@ -266,8 +270,9 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { doc = JSON.parse( doc ); doc.expires = new Date(doc.expires); + var secleft = -1; if ( ('expires' in doc) && _.isDate(doc.expires) ) { - var secleft = doc.expires.getSecondsBetween( now ) * -1; + secleft = doc.expires.getSecondsBetween( now ) * -1; } if (secleft < 0) { self.finished = true; @@ -323,6 +328,7 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.addJob('startRequest', { work: function( api, key, cachedPart, bid ) { + var log = logger.child({bid: bid, key: key, ip: ip}); log.info('manager:startRequest: ' + key); @@ -342,11 +348,11 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { } manager.enqueue('finishRequest', cachedPart ); self.finished = true; - }, api.timeout, self) + }, api.timeout, self); } api.resource( api.params, api.credentials, function( err, res ) { - clearTimeout(self.timeout) + clearTimeout(self.timeout); delete self.timeout; if ( err ) { @@ -392,10 +398,12 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { self.finished = true; }); } - }) + }); manager.addJob('finishRequest', { work: function(apiResponse) { + var key = apiResponse.cname; + var log = logger.child({bid: bid, key: key, ip: ip}); log.info('manager:finishRequest'); @@ -405,9 +413,9 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { thisResponse["redirect"] = apiResponse.redirect; thisResponse["guid"] = apiResponse.guid || ''; thisResponse["authBundle"] = bid; - thisResponse["authPart"] = apiResponse.cname; + thisResponse["authPart"] = key; } - thisResponse[apiResponse.cname] = apiResponse; + thisResponse[key] = apiResponse; if (queriesInThisBundle === 0) { manager.enqueue('composeResponse', bid); @@ -428,11 +436,11 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { }; if (_.has( thisResponse, 'redirect')) { - tout.redirect = thisResponse.redirect, - tout.guid = thisResponse.guid, - tout.authBundle = thisResponse.authBundle, - tout.authPart = thisResponse.authPart - }; + tout.redirect = thisResponse.redirect; + tout.guid = thisResponse.guid; + tout.authBundle = thisResponse.authBundle; + tout.authPart = thisResponse.authPart; + } // Insert api responses into bundle _.each( thisResponse, function( val, idx ) { @@ -506,4 +514,4 @@ exports.fulfill = function ( myRes, ip, bid, callback, gzip, override ) { manager.enqueue('fulfillBundle'); } -} +}; diff --git a/lib/oauth.js b/lib/oauth.js index 4de6efc..9b5fa25 100644 --- a/lib/oauth.js +++ b/lib/oauth.js @@ -1,7 +1,7 @@ var redis = require("redis") , _ = require('underscore')._ , neuron = require('neuron') - , log = require('./logging').log + , logger = require('./logging').log , oauth = require('oauth').OAuth , uuid = require("node-uuid") ; @@ -23,7 +23,9 @@ if (GLOBAL.config.redis.auth) { var manager = new neuron.JobManager(); manager.addJob('finishAuth', { - work: function( tout, cb, authParams ) { + work: function( tout, bid, key, cb, authParams ) { + var log = logger.child({bid: bid, key: key}); + log.info('Run job oauth:finishAuth'); cb(tout, authParams); this.finished = true; } @@ -31,7 +33,8 @@ manager.addJob('finishAuth', { manager.addJob('getTemporaryCredentials', { work: function( api, bid, key, cb ) { - + var log = logger.child({bid: bid, key: key}); + log.info ('getTemporaryCredentials called for ' + bid + ', ' + key); var oaData = GLOBAL.config.authentication[api.auth.provider]; @@ -47,7 +50,7 @@ manager.addJob('getTemporaryCredentials', { oa.getOAuthRequestToken(function(error, oauth_token, oauth_token_secret, results){ if(error) { log.error(error); - manager.enqueue('finishAuth', error, cb); + manager.enqueue('finishAuth', error, bid, key, cb); self.finished = true; } else { api.credentials = { @@ -65,7 +68,7 @@ manager.addJob('getTemporaryCredentials', { guid: uuid.v4() }; log.debug('Authorize redirect response:' + JSON.stringify(tout)); - manager.enqueue('finishAuth', tout, cb); + manager.enqueue('finishAuth', tout, bid, key, cb); self.finished = true; } }); @@ -74,7 +77,8 @@ manager.addJob('getTemporaryCredentials', { manager.addJob('getAccessToken', { work: function(api, bid, key, oauth_token, oauth_verifier, cb) { - + var log = logger.child({bid: bid, key: key}); + log.info('Running getAccessToken for ' + bid + ', ' + key); var oaData = GLOBAL.config.authentication[api.auth.provider], self = this; @@ -94,7 +98,7 @@ manager.addJob('getAccessToken', { if(error) { // handle error log.error(error); - manager.enqueue('finishAuth', error, cb); + manager.enqueue('finishAuth', error, bid, key, cb); self.finished = true; } else { api.credentials.oauth_access_token = oauth_access_token; @@ -108,7 +112,7 @@ manager.addJob('getAccessToken', { err: {errnum:1, errtxt:"Authentication provider requires code."}, cname: key }; - manager.enqueue('finishAuth', tout, cb, { + manager.enqueue('finishAuth', tout, bid, key, cb, { "oauth_consumer_key": api.credentials.oauth_consumer_key, //"oauth_nonce": bid+","+key, //"oauth_signature": xxx, @@ -120,9 +124,10 @@ manager.addJob('getAccessToken', { } }); } -}) +}); exports.authorize = function( api, bid, key, cb ) { + var log = logger.child({bid: bid, key: key}); log.info('oauth authorize called for ' + bid +', ' + key); @@ -145,7 +150,7 @@ exports.authorize = function( api, bid, key, cb ) { api.credentials = JSON.parse(doc); if (_.has(api.credentials, 'oauth_access_token')) { - manager.enqueue('finishAuth', true, cb, { + manager.enqueue('finishAuth', true, bid, key, cb, { "oauth_consumer_key": api.credentials.oauth_consumer_key, //"oauth_nonce": bid+","+key, //"oauth_signature": xxx, @@ -159,10 +164,11 @@ exports.authorize = function( api, bid, key, cb ) { } }); -} +}; exports.saveOauthToken = function( api, oauth_token, oauth_verifier, bid, key, cb) { - + var log = logger.child({bid: bid, key: key}); + log.info('Running saveOauthToken for ' + bid + ', ' + key); client.get(bid+key+'oauth', function(err, doc) { @@ -173,12 +179,12 @@ exports.saveOauthToken = function( api, oauth_token, oauth_verifier, bid, key, c api.credentials = JSON.parse(doc); if (oauth_verifier) api.credentials.oauth_verifier = oauth_verifier; - manager.enqueue('getAccessToken', api, bid, key, oauth_token, oauth_verifier, cb) + manager.enqueue('getAccessToken', api, bid, key, oauth_token, oauth_verifier, cb); } }); -} +}; -exports.OAuth = oauth \ No newline at end of file +exports.OAuth = oauth; \ No newline at end of file diff --git a/lib/oauth2.js b/lib/oauth2.js index c5b9dc4..28450ca 100644 --- a/lib/oauth2.js +++ b/lib/oauth2.js @@ -1,7 +1,7 @@ var redis = require("redis") , _ = require('underscore')._ , neuron = require('neuron') - , log = require('./logging').log + , logger = require('./logging').log , oauth2 = require('oauth').OAuth2 ; @@ -22,7 +22,8 @@ if (GLOBAL.config.redis.auth) { var manager = new neuron.JobManager(); manager.addJob('finishAuth', { - work: function( tout, cb, authParams ) { + work: function( tout, bid, key, cb, authParams ) { + var log = logger.child({bid: bid, key: key}); log.info('Run job oauth2:finishAuth'); cb(tout, authParams); } @@ -30,7 +31,8 @@ manager.addJob('finishAuth', { manager.addJob('getCode', { work: function( api, bid, key, cb ) { - + var log = logger.child({bid: bid, key: key}); + log.info('Run job oauth2:getCode'); var oaData = GLOBAL.config.authentication[api.auth.provider]; @@ -58,7 +60,7 @@ manager.addJob('getCode', { log.debug(JSON.stringify(tout)); - manager.enqueue('finishAuth', tout, cb); + manager.enqueue('finishAuth', tout, bid, key, cb); self.finished = true; } }); @@ -66,6 +68,8 @@ manager.addJob('getCode', { manager.addJob('getAccessToken', { work: function(api, bid, key, cb, grant_type) { + var log = logger.child({bid: bid, key: key}); + log.info('Run job oauth2:getAccessToken(' + grant_type + ')'); var oaData = GLOBAL.config.authentication[api.auth.provider], self = this; @@ -73,8 +77,7 @@ manager.addJob('getAccessToken', { oaData.client_secret, oaData.baseSite, oaData.authorizePath, - oaData.accessTokenPath), - self = this; + oaData.accessTokenPath); log.debug('api = ' + JSON.stringify(api)); log.info('oaData = ' + JSON.stringify(oaData)); @@ -82,7 +85,7 @@ manager.addJob('getAccessToken', { var params = { "grant_type": grant_type - } + }; var thisCode = api.credentials.code; @@ -104,7 +107,7 @@ manager.addJob('getAccessToken', { err: error, cname: key }; - manager.enqueue('finishAuth', tout, cb); + manager.enqueue('finishAuth', tout, bid, key, cb); self.finsihed = true; } else { log.debug('access_token = '+access_token); @@ -125,15 +128,16 @@ manager.addJob('getAccessToken', { client.set(bid+key+'oauth2', JSON.stringify(api.credentials)); log.debug(bid+key+'oauth2 saved'); - manager.enqueue('finishAuth', true, cb, { "access_token": api.credentials.access_token }); + manager.enqueue('finishAuth', true, bid, key, cb, { "access_token": api.credentials.access_token }); self.finished = true; } }); } -}) +}); exports.authorize = function( api, bid, key, cb ) { - + var log = logger.child({bid: bid, key: key}); + log.info('function oauth2:authorize'); // See if we have an oauth record in the database @@ -152,7 +156,7 @@ exports.authorize = function( api, bid, key, cb ) { if (api.credentials.expires.isBefore(new Date())) { manager.enqueue('getAccessToken', api, bid, key, cb, 'refresh_token' ); } else { - manager.enqueue('finishAuth', true, cb, { "access_token": api.credentials.access_token }); + manager.enqueue('finishAuth', true, bid, key, cb, { "access_token": api.credentials.access_token }); } } else { manager.enqueue('getAccessToken', api, bid, key, cb, 'authorization_code' ); @@ -160,19 +164,21 @@ exports.authorize = function( api, bid, key, cb ) { } }); -} +}; exports.saveCode = function( res, state, code, cb) { - + var bid = state[0], key = state[1]; + var log = logger.child({bid: bid, key: key}); + log.info('function oauth2:saveCode'); var doc = {"code": code }; - client.set(state[0]+state[1]+'oauth2', JSON.stringify(doc)); + client.set(bid+key+'oauth2', JSON.stringify(doc)); var tout = { expires: new Date(), - redirect: GLOBAL.config.url + '/bundle/' + state[0] - } + redirect: GLOBAL.config.url + '/bundle/' + bid + }; - manager.enqueue('finishAuth', tout, cb); + manager.enqueue('finishAuth', tout, bid, key, cb); -} +}; From 09af71830e16475c4d5fd0084013eefbb0ce4d0f Mon Sep 17 00:00:00 2001 From: Son Tran-Nguyen Date: Wed, 15 Jul 2015 14:56:32 +0700 Subject: [PATCH 6/6] Support logging to Loggy Requires setting environment variables `LOG_TOKEN` and `LOG_SUBDOMAIN" (optional), i.e.: ``` LOG_TOKEN=xxxxxxxx LOG_SUBDOMAIN=spas node spas --dev --log=verbose ``` --- lib/engine.js | 6 ++++-- lib/logging.js | 15 ++++++++++++--- package.json | 4 ++-- spas.js | 3 +-- 4 files changed, 19 insertions(+), 9 deletions(-) diff --git a/lib/engine.js b/lib/engine.js index 87853d8..d39600e 100644 --- a/lib/engine.js +++ b/lib/engine.js @@ -104,16 +104,18 @@ var sendResponse = function(jDoc, myRes, ip, bid, callback, gzip) { responseHeaders['content-encoding'] = 'gzip'; zlib.gzip(doc, function(err, zbuf) { if (!err) { - log.event('Send gzipped response for ' + bid +', ' + zbuf.toString().length + ', ' + ip); + var size = zbuf.toString().length; + log.event({size: size}, 'Send gzipped response for ' + bid +', ' + size + ', ' + ip); myRes.writeHead(200, responseHeaders); myRes.end(zbuf); } }); } else { // If a callback name was passed, use it. Otherwise, just output the object + var size = doc.length; var tbuf = new Buffer(doc); myRes.writeHead(200, responseHeaders); - log.event('Send response for ' + bid +', ' + doc.length + ', ' + ip); + log.event({size: size}, 'Send response for ' + bid +', ' + size + ', ' + ip); myRes.end(tbuf); } diff --git a/lib/logging.js b/lib/logging.js index 04807de..b717667 100644 --- a/lib/logging.js +++ b/lib/logging.js @@ -16,6 +16,7 @@ var Logger = require('bunyan') +, Bunyan2Loggly = require('bunyan-loggly').Bunyan2Loggly ; /* @@ -61,6 +62,17 @@ if (GLOBAL.config.args.spawned) { }); } +if (process.env.LOG_TOKEN) { + streams.push({ + type: 'raw', + stream: new Bunyan2Loggly({ + token: process.env.LOG_TOKEN, + subdomain: process.env.LOG_SUBDOMAIN || 'spas', + }, (process.env.LOG_BUFFER || 5)), + level: 'trace' + }); +} + var logger = Logger.createLogger({ name: 'SPAS', streams: streams @@ -70,7 +82,4 @@ Logger.prototype.event = function() { this.debug.apply(this, arguments); }; -// Backward compatibility -//logger.event = logger.debug; - exports.log = logger; \ No newline at end of file diff --git a/package.json b/package.json index da2f7b0..c76c862 100644 --- a/package.json +++ b/package.json @@ -27,16 +27,16 @@ "spas": "./bin/spas" }, "scripts": { - "start" : "node spas", + "start": "node spas", "test": "./node_modules/vows/bin/vows ./test/*.js" }, "dependencies": { "bunyan": "^1.4.0", + "bunyan-loggly": "0.0.5", "connect": "2.8.5", "cron": "1.0.1", "date-utils": "1.2.14", "director": "1.2.0", - "loggly": "^1.0.8", "nconf": "0.6.7", "neuron": "0.4.5", "node-uuid": "1.4.1", diff --git a/spas.js b/spas.js index d23d106..5da015e 100644 --- a/spas.js +++ b/spas.js @@ -56,8 +56,7 @@ var // Other Dependencies director = require('director'), - _ = require('underscore')._, - client = require("loggly") + _ = require('underscore')._ ; if (GLOBAL.config.args.create) {