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 a5c821b..b717667 100644 --- a/lib/logging.js +++ b/lib/logging.js @@ -15,45 +15,71 @@ */ var - winston = require('winston') + Logger = require('bunyan') +, Bunyan2Loggly = require('bunyan-loggly').Bunyan2Loggly ; - - -// 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 Winston logging + Configure Bunyan logging */ -var logger = new (winston.Logger)({ - levels: loggingLevels.levels, - colors: loggingLevels.colors, - transports: [] -}); +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 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: level + }); + } 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: level + }); } -exports.winston = logger; \ No newline at end of file +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 +}); + +Logger.prototype.event = function() { + this.debug.apply(this, arguments); +}; + +exports.log = logger; \ No newline at end of file diff --git a/lib/oauth.js b/lib/oauth.js index b3759e1..9b5fa25 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 + , 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,8 +33,9 @@ manager.addJob('finishAuth', { manager.addJob('getTemporaryCredentials', { work: function( api, bid, key, cb ) { - - winston.info ('getTemporaryCredentials called for ' + bid + ', ' + key); + var log = logger.child({bid: bid, key: key}); + + log.info ('getTemporaryCredentials called for ' + bid + ', ' + key); var oaData = GLOBAL.config.authentication[api.auth.provider]; var oa = new oauth(oaData.requestTemporaryCredentials, @@ -46,8 +49,8 @@ manager.addJob('getTemporaryCredentials', { oa.getOAuthRequestToken(function(error, oauth_token, oauth_token_secret, results){ if(error) { - winston.error(error); - manager.enqueue('finishAuth', error, cb); + log.error(error); + manager.enqueue('finishAuth', error, bid, key, cb); self.finished = true; } else { api.credentials = { @@ -64,8 +67,8 @@ manager.addJob('getTemporaryCredentials', { cname: key, guid: uuid.v4() }; - winston.debug('Authorize redirect response:' + JSON.stringify(tout)); - manager.enqueue('finishAuth', tout, cb); + log.debug('Authorize redirect response:' + JSON.stringify(tout)); + manager.enqueue('finishAuth', tout, bid, key, cb); self.finished = true; } }); @@ -74,8 +77,9 @@ manager.addJob('getTemporaryCredentials', { manager.addJob('getAccessToken', { work: function(api, bid, key, oauth_token, oauth_verifier, cb) { - - winston.info('Running getAccessToken for ' + bid + ', ' + key); + 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; @@ -87,14 +91,14 @@ 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); - manager.enqueue('finishAuth', error, cb); + log.error(error); + 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,14 +124,15 @@ manager.addJob('getAccessToken', { } }); } -}) +}); exports.authorize = function( api, bid, key, cb ) { + var log = logger.child({bid: bid, key: key}); - 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; } @@ -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,11 +164,12 @@ 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); + 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 37e2ec7..28450ca 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 + , logger = require('./logging').log , oauth2 = require('oauth').OAuth2 ; @@ -22,16 +22,18 @@ if (GLOBAL.config.redis.auth) { var manager = new neuron.JobManager(); manager.addJob('finishAuth', { - work: function( tout, cb, authParams ) { - winston.info('Run job oauth2:finishAuth'); + work: function( tout, bid, key, cb, authParams ) { + var log = logger.child({bid: bid, key: key}); + log.info('Run job oauth2:finishAuth'); cb(tout, authParams); } }); manager.addJob('getCode', { work: function( api, bid, key, cb ) { - - winston.info('Run job oauth2:getCode'); + var log = logger.child({bid: bid, key: key}); + + log.info('Run job oauth2:getCode'); var oaData = GLOBAL.config.authentication[api.auth.provider]; @@ -56,9 +58,9 @@ manager.addJob('getCode', { cname: key }; - winston.debug(JSON.stringify(tout)); + log.debug(JSON.stringify(tout)); - manager.enqueue('finishAuth', tout, cb); + manager.enqueue('finishAuth', tout, bid, key, cb); self.finished = true; } }); @@ -66,23 +68,24 @@ manager.addJob('getCode', { manager.addJob('getAccessToken', { work: function(api, bid, key, cb, grant_type) { - winston.info('Run job oauth2:getAccessToken(' + 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; var oa = new oauth2(oaData.client_id, oaData.client_secret, oaData.baseSite, oaData.authorizePath, - oaData.accessTokenPath), - self = this; + oaData.accessTokenPath); - 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 = { "grant_type": grant_type - } + }; var thisCode = api.credentials.code; @@ -92,49 +95,50 @@ 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, cname: key }; - manager.enqueue('finishAuth', tout, cb); + manager.enqueue('finishAuth', tout, bid, key, 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'); - manager.enqueue('finishAuth', true, cb, { "access_token": api.credentials.access_token }); + log.debug(bid+key+'oauth2 saved'); + manager.enqueue('finishAuth', true, bid, key, cb, { "access_token": api.credentials.access_token }); self.finished = true; } }); } -}) +}); exports.authorize = function( api, bid, key, cb ) { - - winston.info('function oauth2:authorize'); + var log = logger.child({bid: bid, key: key}); + + log.info('function oauth2:authorize'); // See if we have an oauth record in the database client.get(bid+key+'oauth2', function (err, doc) { @@ -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) { - - winston.info('function oauth2:saveCode'); + 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); -} +}; 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/package.json b/package.json index 7dea9db..c76c862 100644 --- a/package.json +++ b/package.json @@ -26,12 +26,17 @@ "bin": { "spas": "./bin/spas" }, + "scripts": { + "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", @@ -42,8 +47,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" diff --git a/spas.js b/spas.js index 45c11ab..5da015e 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'), @@ -56,8 +56,7 @@ var // Other Dependencies director = require('director'), - _ = require('underscore')._, - client = require("loggly") + _ = require('underscore')._ ; if (GLOBAL.config.args.create) { @@ -109,8 +108,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 +151,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 +168,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 +208,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); } 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