logging engine added, much better logs now

lib/cli.js

@@ -1,10 +1,13 @@
 #!/usr/bin/env node
 
+var logger = require('./logger');
+logger.setup(); // default setup
+
 var pkg_file = '../package.yaml';
 var fs = require('fs');
 var yaml = require('js-yaml');
 var commander = require('commander');
-var server = require('../lib/index');
+var server = require('./index');
 var crypto = require('crypto');
 var pkg = require(pkg_file);
 
@@ -64,12 +67,8 @@ try {
 		}
 	}
 } catch(err) {
-	if (err.code === 'ENOENT') {
-		console.error('ERROR: cannot open configuration file "'+config_path+'", file not found');
-		process.exit(1);
-	} else {
-		throw err;
-	}
+	logger.logger.fatal({file: config_path, err: err}, 'cannot open config file @{file}: @{!err.message}');
+	process.exit(1);
 }
 
 if (!have_question) afterConfigLoad();
@@ -94,7 +93,7 @@ function afterConfigLoad() {
 
 	var hostport = get_hostport();
 	server(config).listen(hostport[1], hostport[0]);
-	console.log('Server is listening on http://%s:%s/', hostport[0], hostport[1]);
+	logger.logger.warn({addr: 'http://'+hostport[0]+':'+hostport[1]+'/'}, 'Server is listening on @{addr}');
 
 	// undocumented stuff for tests
 	if (typeof(process.send) === 'function') {

lib/config.js

@@ -26,10 +26,10 @@ function Config(config) {
 	
 	assert(this.storage, 'CONFIG: storage path not defined');
 
-	var users = {all:true, anonymous:true, owner:true, none:true};
+	var users = {all:true, anonymous:true, 'undefined':true, owner:true, none:true};
 	
 	var check_user_or_uplink = function(arg) {
-		assert(arg !== 'all' || arg !== 'owner' || arg !== 'anonymous' || arg !== 'none', 'CONFIG: reserved user/uplink name: ' + arg);
+		assert(arg !== 'all' || arg !== 'owner' || arg !== 'anonymous' || arg !== 'undefined' || arg !== 'none', 'CONFIG: reserved user/uplink name: ' + arg);
 		assert(!arg.match(/\s/), 'CONFIG: invalid user name: ' + arg);
 		assert(users[arg] == null, 'CONFIG: duplicate user/uplink name: ' + arg);
 		users[arg] = true;

lib/config_def.yaml

@@ -21,7 +21,7 @@ packages:
 
   '*':
     # allow all users to read packages ('all' is a keyword)
-    # this includes non-authenticated (anonymous) users
+    # this includes non-authenticated users
     allow_access: all
 
     # allow 'admin' to publish packages
@@ -43,3 +43,14 @@ packages:
 # you can specify listen address (or simply a port)
 #listen: localhost:4873
 
+# type: file | stdout | stderr
+# level: trace | debug | info | http (default) | warn | error | fatal
+#
+# parameters for file: name is filename
+#  {type: 'file', path: 'sinopia.log', level: 'debug'},
+#
+# parameters for stdout and stderr: format: json | pretty
+#  {type: 'stdout', format: 'pretty', level: 'debug'},
+log:
+  - {type: stdout, format: pretty, level: http}
+  #- {type: file, path: sinopia.log, level: info}

lib/index.js

@@ -4,11 +4,11 @@ var utils = require('./utils');
 var Storage = require('./storage');
 var Config = require('./config');
 var UError = require('./error').UserError;
-var basic_auth = require('./middleware').basic_auth;
-var validate_name = require('./middleware').validate_name;
-var media = require('./middleware').media;
-var etagify = require('./middleware').etagify;
-var expect_json = require('./middleware').expect_json;
+var Middleware = require('./middleware');
+var basic_auth = Middleware.basic_auth;
+var validate_name = Middleware.validate_name;
+var media = Middleware.media;
+var expect_json = Middleware.expect_json;
 
 module.exports = function(config_hash) {
 	var config = new Config(config_hash);
@@ -19,7 +19,7 @@ module.exports = function(config_hash) {
 			if (config['allow_'+action](req.params.package, req.remoteUser)) {
 				next();
 			} else {
-				if (req.remoteUser === 'anonymous') {
+				if (!req.remoteUser) {
 					next(new UError({
 						status: 403,
 						msg: "can't "+action+" restricted package without auth, did you forget 'npm set always-auth true'?",
@@ -35,8 +35,7 @@ module.exports = function(config_hash) {
 	};
 
 	var app = express();
-	app.use(express.logger());
-	app.use(etagify);
+	app.use(Middleware.log_and_etagify);
 	app.use(basic_auth(function(user, pass) {
 		return config.authenticate(user, pass);
 	}));

lib/logger.js

@@ -0,0 +1,144 @@
+var Logger = require('bunyan');
+var Stream = require('stream');
+
+function getlvl(x) {
+	if (x < 15) {
+		return 'trace';
+	} else if (x < 25) {
+		return 'debug';
+	} else if (x < 35) {
+		return 'info';
+	} else if (x == 35) {
+		return 'http';
+	} else if (x < 45) {
+		return 'warn';
+	} else if (x < 55) {
+		return 'error';
+	} else {
+		return 'fatal';
+	}
+}
+
+module.exports.setup = function(logs) {
+	var streams = [];
+	if (!logs) logs = [{ type: 'stdout', format: 'pretty', level: 'http' }];
+
+	logs.forEach(function(target) {
+		var stream = new Stream();
+		stream.writable = true;
+
+		if (target.type === 'stdout' || target.type === 'stderr') {
+			// destination stream
+			var dest = target.type === 'stdout' ? process.stdout : process.stderr;
+
+			if (target.format === 'pretty') {
+				// making fake stream for prettypritting
+				stream.write = function(obj) {
+					dest.write(print(obj.level, obj.msg, obj) + "\n");
+				}
+			} else {
+				stream.write = function(obj) {
+					obj = log_filter(obj);
+					dest.write(JSON.stringify(obj, Logger.safeCycles()) + "\n");
+				}
+			}
+		} else if (target.type === 'file') {
+			var dest = require('fs').createWriteStream(target.path, {flags: 'a', encoding: 'utf8'});
+			dest.on('error', function (err) {
+				Logger.emit('error', err);
+			});
+			stream.write = function(obj) {
+				obj = log_filter(obj);
+				dest.write(JSON.stringify(obj, Logger.safeCycles()) + "\n");
+			}
+		} else {
+			throw new Error('wrong target type for a log');
+		}
+
+		if (target.level === 'http') target.level = 35;
+		streams.push({
+			type: "raw",
+			level: target.level || 35,
+			stream: stream,
+		});
+	});
+
+	var logger = new Logger({
+		name: 'sinopia',
+		streams: streams,
+		serializers: {
+			err: Logger.stdSerializers.err,
+			req: Logger.stdSerializers.req,
+			res: Logger.stdSerializers.res,
+		},
+	});
+
+	module.exports.logger = logger;
+}
+
+// adopted from socket.io
+// this part was converted to coffee-script and back again over the years,
+// so it might look weird
+
+// level to color
+var levels = {
+	fatal: 31,
+	error: 31,
+	warn: 33,
+	http: 35,
+	info: 36,
+	debug: 90,
+	trace: 90,
+};
+
+var max = 0;
+for (var l in levels) {
+	max = Math.max(max, l.length);
+}
+
+function pad(str) {
+	if (str.length < max) return str + new Array(max - str.length + 1).join(' ');
+	return str;
+};
+
+var subsystems = {
+	in: '\x1b[32m<--\x1b[39m',
+	out: '\x1b[33m-->\x1b[39m',
+	fs: '\x1b[37m-*-\x1b[39m',
+	default: '\x1b[34m---\x1b[39m',
+};
+
+function print(type, msg, obj) {
+	if (typeof type === 'number') type = getlvl(type);
+	var finalmsg = msg.replace(/@{(!?[$A-Za-z_][$0-9A-Za-z\._]*)}/g, function(_, name) {
+		var str = obj, is_error;
+		if (name[0] === '!') {
+			name = name.substr(1);
+			is_error = true;
+		}
+
+		var _ref = name.split('.');
+		for (var _i = 0; _i < _ref.length; _i++) {
+			var id = _ref[_i];
+			if (typeof str === 'object') {
+				str = str[id];
+			} else {
+				str = void 0;
+			}
+		}
+
+		if (typeof(str) === 'string') {
+			if (is_error) {
+				return '\x1b[31m' + str + '\x1b[39m';
+			} else {
+				return '\x1b[32m' + str + '\x1b[39m';
+			}
+		} else {
+			return require('util').inspect(str, void 0, void 0, true);
+		}
+	});
+	var sub = subsystems[obj.sub] || subsystems.default;
+
+	return " \x1b[" + levels[type] + "m" + (pad(type)) + "\x1b[39m " + sub + " " + finalmsg;
+};
+

lib/middleware.js

@@ -1,6 +1,7 @@
 var crypto = require('crypto');
 var utils = require('./utils');
 var UError = require('./error').UserError;
+var Logger = require('./logger');
 
 module.exports.validate_name = function validate_name(req, res, next, value, name) {
 	if (utils.validate_name(req.params.package)) {
@@ -43,7 +44,7 @@ module.exports.basic_auth = function basic_auth(callback) {
 
 		if (req.user) return next();
 		if (authorization == null) {
-			req.user = req.remoteUser = 'anonymous';
+			req.user = req.remoteUser = undefined;
 			return next();
 		}
 
@@ -85,14 +86,24 @@ function md5sum(data) {
 	return crypto.createHash('md5').update(data).digest('hex');
 }
 
-// using it for json only right now
-module.exports.etagify = function(req, res, next) {
+module.exports.log_and_etagify = function(req, res, next) {
+	// logger
+	req.log = Logger.logger.child({sub: 'in'});
+	req.log.info({req: req, ip: req.ip}, '@{ip} requested \'@{req.method} @{req.url}\'');
+
+	var bytesin = 0;
+	req.on('data', function(chunk){ bytesin += chunk.length });
+
 	var _send = res.send;
 	res.send = function(body) {
+		var error;
 		if (typeof(body) === 'string' || typeof(body) === 'object') {
 			res.header('Content-type', 'application/json');
 
-			if (typeof(body) === 'object') {
+			if (typeof(body) === 'object' && body != null) {
+				if (body.error) {
+					error = body.error;
+				}
 				body = JSON.stringify(body, undefined, '\t');
 			}
 			
@@ -100,7 +111,27 @@ module.exports.etagify = function(req, res, next) {
 		} else {
 			// send(null), send(204), etc.
 		}
-		_send.call(res, body);
+
+		var msg = '@{status}, user: @{user}, req: \'@{request.method} @{request.url}\'';
+		if (error) {
+			msg += ', error: @{!error}';
+		} else {
+			msg += ', bytes: @{bytes.in}/@{bytes.out}';
+		}
+		req.log.warn({
+			request: {method: req.method, url: req.url},
+			level: 35, // http
+			user: req.user,
+			status: res.statusCode,
+			error: error,
+			bytes: {
+				in: bytesin,
+				out: body.length,
+			}
+		}, msg);
+
+		res.send = _send;
+		res.send(body);
 	};
 	next();
 }

lib/up-storage.js

@@ -2,6 +2,7 @@ var URL = require('url');
 var request = require('request');
 var UError = require('./error').UserError;
 var mystreams = require('./streams');
+var Logger = require('./logger');
 
 //
 // Implements Storage interface
@@ -13,6 +14,7 @@ function Storage(config, mainconfig) {
    this.is_alive = false;
 	this.userAgent = mainconfig.user_agent;
 	this.ca = config.ca;
+	this.logger = Logger.logger.child({sub: 'out'});
 
 	this.url = URL.parse(this.config.url);
 	if (this.url.hostname === 'registry.npmjs.org') {
@@ -35,16 +37,61 @@ Storage.prototype.request = function(options, cb) {
 	var headers = options.headers || {};
 	headers.accept = headers.accept || 'application/json';
 	headers['user-agent'] = headers['user-agent'] || this.userAgent;
-	var req = request({
-		url: options.uri_full || (this.config.url + options.uri),
-		method: options.method || 'GET',
+
+	var method = options.method || 'GET';
+	var uri = options.uri_full || (this.config.url + options.uri);
+	var method = options.method || 'GET';
+	self.logger.info({
+		method: method,
 		headers: headers,
-		json: options.json || true,
+		uri: uri,
+	}, "making request: '@{method} @{uri}'");
+
+	if (typeof(options.json) === 'object' && options.json != null) {
+		var json = JSON.stringify(options.json);
+	}
+
+	var req = request({
+		url: uri,
+		method: method,
+		headers: headers,
+		body: json,
 		ca: this.ca,
-	}, function(err) {
+	}, function(err, res, body) {
+		var res_length = body.length;
+		if (options.json) {
+			try {
+				body = JSON.parse(body);
+			} catch(err) {
+				return cb(err);
+			}
+		}
+
+		if (typeof(body) === 'object' && body != null) {
+			if (body.error) {
+				var error = body.error;
+			}
+		}
+
+		var msg = '@{status}, req: \'@{request.method} @{request.url}\'';
+		if (error) {
+			msg += ', error: @{!error}';
+		} else {
+			msg += ', bytes: @{bytes.in}/@{bytes.out}';
+		}
+		self.logger.warn({
+			request: {method: method, url: uri},
+			level: 35, // http
+			status: res.statusCode,
+			error: error,
+			bytes: {
+				in: json ? json.length : 0,
+				out: res_length,
+			}
+		}, msg);
 		if (cb) cb.apply(self, arguments);
 	});
-	req.on('response', function() {
+	req.on('response', function(res) {
 		self.status_check(true);
 	});
 	req.on('error', function() {
@@ -172,7 +219,7 @@ Storage.prototype.get_url = function(url) {
 		uri_full: url,
 		encoding: null,
 	});
-
+	
 	rstream.on('response', function(res) {
 		if (res.statusCode === 404) {
 			return stream.emit('error', new UError({

package.yaml

@@ -26,6 +26,7 @@ dependencies:
   async: '*'
   semver: '*'
   minimatch: '*'
+  bunyan: '>= 0.16.4'
 
 devDependencies:
   rimraf: '*'