diff --git a/app.js b/app.js index f9ccbc6..69aaaa9 100644 --- a/app.js +++ b/app.js @@ -11,8 +11,11 @@ var db = require('./db'), reader = require('./lib/reader'), notifier = require('./lib/notifier'), project = require('./lib/project'), + libLogger = require('./lib/logger'), chokidar = require('chokidar'); +var logger = libLogger('app'); + var staticServer = new nodeStatic.Server('./static'); var server = http.createServer(function(req, res, next) { // serve index for all app pages @@ -39,6 +42,7 @@ var app = { app.lib = {}; app.lib.reader = reader; app.lib.notifier = notifier; +app.lib.logger = libLogger; Steppy( function() { @@ -71,7 +75,7 @@ Steppy( function(err, mkdirResult, config) { _(app.config).defaults(config); - console.log('Server config:', JSON.stringify(app.config, null, 4)); + logger.log('Server config:', JSON.stringify(app.config, null, 4)); notifier.init(app.config.notify, this.slot()); @@ -87,7 +91,7 @@ Steppy( function(err, projects) { // note that `app.projects` is live variable app.projects = projects; - console.log('Loaded projects: ', _(app.projects).pluck('name')); + logger.log('Loaded projects: ', _(app.projects).pluck('name')); // start file watcher for reloading projects on change var syncProject = function(filename, fileInfo) { @@ -102,22 +106,22 @@ Steppy( }); if (projectIndex !== -1) { - console.log('Unload project: "' + projectName + '"'); + logger.log('Unload project: "' + projectName + '"'); app.projects.splice(projectIndex, 1); } // on add or change (info is falsy on unlink) if (fileInfo) { - console.log('Load project "' + projectName + '" on change'); + logger.log('Load project "' + projectName + '" on change'); project.load(baseDir, projectName, function(err, project) { if (err) { - return console.error( + return logger.error( 'Error during load project "' + projectName + '": ', err.stack || err ); } app.projects.push(project); - console.log( + logger.log( 'Project "' + projectName + '" loaded:', JSON.stringify(project, null, 4) ); @@ -137,7 +141,7 @@ Steppy( watcher.on('unlink', syncProject); watcher.on('error', function(err) { - console.error('File watcher error occurred: ', err.stack || err); + logger.error('File watcher error occurred: ', err.stack || err); }); // init resources diff --git a/httpApi/index.js b/httpApi/index.js index ab2950c..87745f6 100644 --- a/httpApi/index.js +++ b/httpApi/index.js @@ -10,7 +10,8 @@ var Steppy = require('twostep').Steppy, exports.register = function(app) { var config = app.config.httpApi, projects = app.projects, - distributor = app.distributor; + distributor = app.distributor, + logger = app.lib.logger('http api'); var server = http.createServer(function(req, res) { Steppy( @@ -38,6 +39,7 @@ exports.register = function(app) { if (project) { res.statusCode = 204; + logger.log('Run "' + projectName + '"'); distributor.run({ projectName: projectName, initiator: {type: 'httpApi'} @@ -48,7 +50,7 @@ exports.register = function(app) { res.end(); }, function(err) { - console.log('Error occurred during request: ', err.stack || err); + logger.error('Error occurred during request: ', err.stack || err); } ); }); diff --git a/lib/distributor.js b/lib/distributor.js index b796bd8..a8e8381 100644 --- a/lib/distributor.js +++ b/lib/distributor.js @@ -6,7 +6,7 @@ var Steppy = require('twostep').Steppy, EventEmitter = require('events').EventEmitter, inherits = require('util').inherits, notifier = require('./notifier'), - utils = require('./utils'); + logger = require('./logger')('distributor'); function Distributor(params) { @@ -80,7 +80,7 @@ Distributor.prototype._runNext = function(callback) { }, function(err, build) { if (err) { - console.error( + logger.error( 'Error during build update: ', err.stack || err ); return stepCallback(err); @@ -110,7 +110,7 @@ Distributor.prototype._runNext = function(callback) { number: build.number, project: {name: build.project.name} }, - }, utils.logErrorCallback); + }); } }); @@ -210,6 +210,11 @@ Distributor.prototype._updateBuild = function(build, changes, callback) { Distributor.prototype.run = function(params, callback) { var self = this, project; + callback = callback || function(err) { + if (err) { + logger.error('Error during run: ', err.stack || err); + } + }; Steppy( function() { project = _(self.projects).findWhere({name: params.projectName}); diff --git a/lib/executor/base.js b/lib/executor/base.js index 09a6f72..5a022aa 100644 --- a/lib/executor/base.js +++ b/lib/executor/base.js @@ -4,8 +4,7 @@ var Steppy = require('twostep').Steppy, path = require('path'), _ = require('underscore'), EventEmitter = require('events').EventEmitter, - inherits = require('util').inherits, - utils = require('../utils'); + inherits = require('util').inherits; function Executor(params) { this.project = params.project; diff --git a/lib/logger.js b/lib/logger.js new file mode 100644 index 0000000..1e684f9 --- /dev/null +++ b/lib/logger.js @@ -0,0 +1,74 @@ +'use strict'; + +var _ = require('underscore'), + util = require('util'), + colors = require('colors/safe'); + +/* + * Borrowed from parking lib/node/utils/logger.js, thanks to @artzhuchka + * TODO: should be separate nmp module + */ +module.exports = function() { + function F(args) { + return Logger.apply(this, args); + } + + F.prototype = Logger.prototype; + + return new F(arguments); +}; + +module.exports.Logger = Logger; + +var methodsHash = { + log: colors.reset, + info: colors.cyan, + warn: colors.yellow, + error: colors.red +}; + +function Logger(name, options) { + this.name = name; + this.options = _({dateTime: true}).extend(options); + this._times = {}; +} + +Logger.prototype._colorizeArgs = function(argsColorFn, args) { + return argsColorFn.call(colors, util.format.apply(util, args)); +}; + +Logger.prototype._formatArgs = function(argsColorFn, args) { + var parts = []; + + if (this.options.dateTime) { + parts.push(colors.gray('[' + new Date().toUTCString() + ']')); + } + + parts = parts.concat([ + colors.green('[' + this.name + ']'), + this._colorizeArgs(argsColorFn, args) + ]); + + return parts.join(' '); +}; + +_(methodsHash).each(function(colorFn, method) { + Logger.prototype[method] = function() { + console.log.call(console, this._formatArgs(colorFn, arguments)); + }; +}); + +Logger.prototype.trace = function(err) { + console.log(this._colorizeArgs(colors.red, [err.stack || err])); +}; + +Logger.prototype.time = function() { + this._times[util.format.apply(util, arguments)] = Date.now(); +}; + +Logger.prototype.timeEnd = function() { + var label = util.format.apply(util, arguments); + var time = this._times[label]; + if (!time) return; + this.log('%s: %dms', label, Date.now() - time); +}; diff --git a/lib/notifier/index.js b/lib/notifier/index.js index 386ae69..466296a 100644 --- a/lib/notifier/index.js +++ b/lib/notifier/index.js @@ -2,8 +2,8 @@ var Steppy = require('twostep').Steppy, _ = require('underscore'), - utils = require('../utils'), - db = require('../../db'); + db = require('../../db'), + logger = require('../logger')('notifier'); var constructors = {}, instances = {}; @@ -48,7 +48,11 @@ exports._getPrevBuild = function(build, callback) { * Check if that's completed build should be notified, then notify */ exports.send = function(build, callback) { - callback = callback || utils.logErrorCallback; + callback = callback || function(err) { + if (err) { + logger.error('Error during send:', err.stack || err); + } + }; Steppy( function() { if (!build.completed) { @@ -91,6 +95,10 @@ exports.send = function(build, callback) { var notifyGroup = this.makeGroup(); _(notify.to).each(function(recipients, type) { + logger.log( + 'Notify about ' + build.project.name + ' build #' + + build.number+ ' "' + strategy + '" via ' + type + ); if (type in instances) { instances[type].send({ build: build, diff --git a/lib/utils.js b/lib/utils.js index 2d05193..3981aef 100644 --- a/lib/utils.js +++ b/lib/utils.js @@ -10,7 +10,3 @@ exports.prune = function(str, length) { return result.replace(/ $/, words.length ? '...' : ''); }; - -exports.logErrorCallback = function(err) { - if (err) console.error(err.stack || err); -}; diff --git a/package.json b/package.json index 942bc41..a29e68b 100644 --- a/package.json +++ b/package.json @@ -29,6 +29,7 @@ "homepage": "https://github.com/okv/nci", "dependencies": { "chokidar": "1.0.3", + "colors": "1.1.2", "data.io": "0.3.0", "jade": "1.9.2", "js-yaml": "3.3.1", diff --git a/resources/errorHandler.js b/resources/errorHandler.js index 0794308..937e875 100644 --- a/resources/errorHandler.js +++ b/resources/errorHandler.js @@ -1,7 +1,9 @@ 'use strict'; +var logger = require('../lib/logger')('resources error handler'); + module.exports = function(err, req, res, next) { - console.error( + logger.error( 'Error is occurred during requesting ' + req.resource.namespace.name + ' ' + req.action + ':', err.stack || err diff --git a/resources/projects.js b/resources/projects.js index 3d6360b..b5dddfc 100644 --- a/resources/projects.js +++ b/resources/projects.js @@ -7,7 +7,7 @@ var Steppy = require('twostep').Steppy, db = require('../db'), path = require('path'), fs = require('fs'), - utils = require('../lib/utils'); + logger = require('../lib/logger')('projects resource'); module.exports = function(app) { @@ -45,11 +45,11 @@ module.exports = function(app) { } var buildDataResource = app.dataio.resource('build' + build.id); buildDataResource.on('connection', function(client) { - var callback = this.async(); - var stream = fs.createReadStream( - getBuildLogPath(build.id), - {encoding: 'utf8'} - ); + var callback = this.async(), + buildLogPath = getBuildLogPath(build.id); + + var stream = fs.createReadStream(buildLogPath, {encoding: 'utf8'}); + stream .on('readable', function() { var data = stream.read(); @@ -59,7 +59,12 @@ module.exports = function(app) { } }) .on('end', callback) - .on('error', utils.logErrorCallback); + .on('error', function(err) { + logger.error( + 'Error during read "' + buildLogPath + '":', + err.stack || err + ); + }); }); buildDataResourcesHash[build.id] = buildDataResource; }; @@ -96,7 +101,12 @@ module.exports = function(app) { writeStreamsHash[filePath] = fs.createWriteStream( getBuildLogPath(build.id), {encoding: 'utf8'} ); - writeStreamsHash[filePath].on('error', utils.logErrorCallback); + writeStreamsHash[filePath].on('error', function(err) { + logger.error( + 'Error during write "' + filePath + '":', + err.stack || err + ); + }); } // TODO: close ended files writeStreamsHash[filePath].write(data); @@ -110,11 +120,11 @@ module.exports = function(app) { resource.use('run', function(req, res) { var projectName = req.data.projectName; - console.log('Run the project: %s', projectName); + logger.log('Run the project: "%s"', projectName); distributor.run({ projectName: projectName, initiator: {type: 'user'} - }, utils.logErrorCallback); + }); res.send(); });