introduce logger

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

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);
 			}
 		);
 	});

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});

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;

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);
+};

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,

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);
-};

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",

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

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();
 	});