Sunride's console.log for Node adds date, file name, line number and function name to log lines

gistfile1.js

// It may be inefficient, and a little fragile (e.g. if Node changes its stacktrace
// formatting), but it can be a nice tool for developers when it works.



// ### sunlogger.js

var Logger = require('devnull');
var logger = new Logger({namespacing : 0});
var fs = require("fs");

// This has become deprecated as a logger in favour of enhance_console_log.js
// But some of its useful functions are being used by that logger, and elsewhere!

// Our core log function.  Currently just adds a date.
function log() {
	//logger.log.apply(logger,arguments);

	// Or with console.log:
	// Add a date to the start of each log message:
	//var args = argumentsToList(arguments);
	//args.unshift("[" + simpleDateString() + "]");
	//console.log.apply(console,args);

	// Or keep using logger, but add filename and line number:
	var args = argumentsToList(arguments);
	var line = getLocationOfCaller();
	args.unshift(line);
	logger.log.apply(logger,args);
}

// More generic logging.  Let's re-use a common method rather than repeat boilerplate code.  This is more semantic and far easier to change/update.
function logError(err) {
	var args = argumentsToList(arguments);
	args.unshift("ERROR:");
	// If the request object was passed during the report, that is useful, *but* it is a big object.  Let's only grab the bits we need.
	for (var i=0;i<args.length;i++) {
		// Crude detection (potential false positives):
		//if (args[i].url) {
		// Fragile detection (potential true negatives, if a req is ever not constructed by 'IncomingMessage' function):
		if (args[i]!=null && args[i].constructor && args[i].constructor.name && args[i].constructor.name==="IncomingMessage") {
			var req = args[i];
			//console.log("Detected req:",req);   // Warning: big!
			// Replace the request object with a summary:
			args[i] = "during request " + summariseRequest(req);
			// We could opt to add the headers here as well.
			// TODO: Parameters in a GET request will be visible.  But we *should* log parameters in a POST request.
		}
	}
	log.apply(this,args); // Does not appear in error stream but does get the benefits of our general logging function.
	//args.unshift("[" + simpleDateString() + "] ERROR:");
	//console.error.apply(console,args);
	// CONSIDER: What hope have we of tracking the "thread" this came from?
	// E.g. If a deep callback fails, we don't really know which HTTP request/user it was related to!  (Could be hard to track in future, with log lines from multiple concurrent users).
	// In Java I used to log Thread IDs from the top of the request, through all the deeper methods it executed, but this is not possible in NodeJS.
	// Our best hope is to encourage callbacks to pass the 'req' object if it is still in scope, and also even some summary of the circumstances (so we can see *where* in the code it was thrown).
	// This is now done automatically during failResponseAndLogError, since we can fish the req object out of the res object.
}

function summariseRequest(req) {
	var userinfo = summariseUser(req);
	return req.method+" "+req.path+" ("+userinfo+" @ "+req.ip+") ["+req.header("Accept")+"]";
	// Other interesting properties of req:
	//   req._route_index (indicates the handler function number?)
	//   req.sessionID (could track non-logged-in users between requests, separate those from shared IP)
	//   req.headers (note: an object, not an array)
}

function summariseUser(req) {
	return typeof req.session.user === "undefined" ? "_unknown_" : req.session.user.username + " id:"+req.session.user._id;
}

// I was stupid.  Array.prototype.slice.apply works fine, as long as we give it [0] or nothing.  I was giving it 0 duh.
function argumentsToList(args) {
	/*
	var list = [];
	for (var i=0;i<args.length;i++) {
		list[i] = args[i];   // Apparently faster than .push
	}
	return list;
	*/
	return Array.prototype.slice.apply(args);
}

function simpleDateString(date) {
	date = date || new Date();
	var today = date.getFullYear()+"/"+padLeft(date.getMonth()+1,2,'0')+"/"+padLeft(date.getDate(),2,'0');
	return today + " " + date.toLocaleTimeString();
}

function getStackTrace(linesToDrop) {
	var stack;
	try {
		throw new Error("DUMMY_ERROR_FOR_STACKTRACE");
	} catch (e) {
		stack = e.stack || "no_stacktrace_found for "+err;
		if (typeof linesToDrop == "number") {
			linesToDrop += 2;   // Also drop the error message, and the call to this function.
			var stackElements = (""+stack).split("\n");
			stackElements.splice(0,linesToDrop);
			stack = stackElements.join("\n");
		}
	}
	// Note that this throw-and-catch trick can also be used in browsers, and even in Java, whenever we want to find the filename and line number of the function call which called us.  This can be used by loggers to infuse innocent log or info messages with filenames and line numbers, even if no errors were involved.
	return stack;
}

var longestCodeLocation = 0;
function getLocationOfCaller(linesToDrop) {
	if (typeof linesToDrop != "number") {
		linesToDrop = 0;
	}
	var stack = getStackTrace(linesToDrop+2);
	var lines = stack.split("\n");
	// Sometimes we are deep inside our logging functions.  We can skip some of them.
	lines = lines.filter(function(line){
		return !line.match(/ at (logRequest|logError|Object\.logError) /);
	});
	var firstLine = lines[0];
	var codeLocation;
	//console.log(stack);
	try {
		// codeLocation = firstLine.match(/\((.*)\)$/)[0];   // Pick out just the filename/number
		// codeLocation = firstLine.replace(/^ *at /,'');   // Keep the function name, reject ever-present stuff
		// codeLocation = firstLine.replace(/^ *at (.*) \((.*)\)$/,'($2|$1)');   // Same but switch order and reformat

		// Reduce the length of the string by dropping current folder.
		//var workingFolder = fs.realpathSync(.);
		//codeLocation = codeLocation.replace(workingFolder+"/",'');

		// Extract the bits, minify them, and recombine them.
		//console.log(firstLine);
		// I usually expect lines like this:
		//    at Router._dispatch (/Users/joey/citizenpower/node_modules/express/lib/router/index.js:170:5)
		// But some lines on Mac have no function name, and no brackets around the path:
		//    at /Users/joey/citizenpower/routes/routes.js:182:3
		var match = firstLine.match(/^ *at (.*) \((.*)\)$/);
		var functionPath, filenameAndLinenumber;
		if (match) {
			functionPath = match[1];
			filenameAndLinenumber = match[2];
		} else { // Mac
			match = firstLine.match(/^ *at (.*)$/);
			functionPath = "_unknown_";
			filenameAndLinenumber = match[1];
		}
		filenameAndLinenumber = filenameAndLinenumber.split("/").slice(-2).join("/");
		functionPath = functionPath.split(".").slice(-3).join(".");
		codeLocation = "(" + filenameAndLinenumber + "|" + functionPath + ")";

	} catch (e) {
		//codeLocation = "getLocationOfCaller_FAILED:"+e;
		//codeLocation = "CouldNotFindLocationIn >>"+firstLine+"<<";
		codeLocation = "_no_location_";
	}

	// But let's apply a limit to this. Some locations are very long; these will not affect our padding.
	if (codeLocation.length < 60) {
		// We left-align all log messages (although not pre-emptively).
		longestCodeLocation = Math.max(longestCodeLocation, codeLocation.length);
	}
	codeLocation = padRight(codeLocation,longestCodeLocation);

	return codeLocation;
	// DONE: Some of the reported "function names" can get quite long, e.g.
	//   "module.exports.app.post.projectProvider.update.name"
	//   "Promise.module.exports.app.get.Project.findByName.populate.exec.res.render.project"
	// We may want to reduce them to the last few parts?
	// The same may be considered for filenames too:
	//   node_modules/express/lib/router/index.js
	// (In Java I usually logged the class and method name, but not the class's package!)
}

function padLeft(str,len,padChar) {
	padChar = padChar || ' ';
	str = ""+str;
	while (str.length < len) {
		str = padChar + str;
	}
	return str;
}

function padRight(str,len,padChar) {
	padChar = padChar || ' ';
	str = ""+str;
	while (str.length < len) {
		str += padChar;
	}
	return str;
}


module.exports = {
	log: log,
	logError: logError,
	summariseRequest: summariseRequest,
	summariseUser: summariseUser,   // NOTE: Accepts a request, not a user!
	argumentsToList: argumentsToList,
	getStackTrace: getStackTrace,
	getLocationOfCaller: getLocationOfCaller,
	simpleDateString: simpleDateString,
	padLeft: padLeft,
	padRight: padRight
};



// ### enhance_console_log.js

// enhance_console_log
// Replaces console.log .info .warn and .error with our own custom versions.
// So ALL future calls to console.log etc. will go through here.
// Currently our custom logger adds location-of-caller and a simple date, using tools from sunlogger.

//var Logger = require('devnull');
//var logger = new Logger({namespacing : 0});
var sunlogger = require('./sunlogger');
var tty = require("tty");
var colors = require("colors");

var isAtty = tty.isatty(process.stdout.fd);

var realLogFunctions = {};
console.realLogFunctions = realLogFunctions;

function adapted(level) {
	return function() {
		var args = sunlogger.argumentsToList(arguments);
		var line = sunlogger.getLocationOfCaller();
		args.unshift(addColorTo(line,level));
		args.unshift(addColorTo("["+level+"]",level));
		// We can get away with this.  It seems Logger/logger does grab a copy of console.log before we modify it.
		// But it seems logger does not have .warn .info .error (since it uses its own numerical levels instead).  Perhaps then we should create four devnull loggers.
		//logger.log.apply(logger,args);
		args.unshift(addColorTo(sunlogger.simpleDateString(),level));
		realLogFunctions[level].apply(null,args);
	};
}

var levelsToColor = {
	debug: "grey",
	log:   "white",
	info:  "cyan",
	warn:  "yellow",
	error: "red"
};

function addColorTo(str, level) {
	// In development mode, we will log colors *even* if tee-ing to a file.
	if (process.env.NODE_ENV != "production" || isAtty) {
		var col = levelsToColor[level];
		if (col) {
			str = str[col];
		}
		if (level != 'log') {
			str = str.bold;
		}
	}
	return str;
}

var toAdapt = ["log", "info", "warn", "error"];

toAdapt.forEach(function(level){
	realLogFunctions[level] = console[level];
	global.console[level] = adapted(level);
});