Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

bot: use a logger properly, pass it to modules #143

Merged
merged 6 commits into from
Jun 28, 2017
Merged

bot: use a logger properly, pass it to modules #143

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
db2c38b
deps: add dependency on bunyan :deciduous_tree:
euank Jun 26, 2017
2129ee0
bot: add trace logging, fix loglevel config
euank Jun 26, 2017
bf60e32
module-manager: pass logger to modules
euank Jun 26, 2017
d286fae
modules: add testlog module
euank Jun 26, 2017
ed4acd6
module-manager: remove name resolution helper
euank Jun 28, 2017
4323279
testlog: add exhaustive examples
euank Jun 28, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
50 changes: 36 additions & 14 deletions bot.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,13 @@ var irc = require('irc'),
path = require('path'),
moduleMan = require("./node-module-manager"),
changeCase = require('change-case'),
SnailEscape = require('snailescape.js');
SnailEscape = require('snailescape.js'),
bunyan = require('bunyan');

var log = bunyan.createLogger({
name: "euircbot",
serializers: {err: bunyan.stdSerializers.err},
});

var heapdump = null;

Expand All @@ -22,10 +28,10 @@ bot.util = {}; //Util functions

bot.init = function(cb) {
if(bot.config.heapdump) {
console.log("Enabling heap dumps");
log.debug("enabling heap dumps");
heapdump = require('heapdump');
process.on('SIGINT', function() {
console.log("Please stand by...");
log.warn("dumping heap, if configured, and exiting");
bot.dump();
process.exit();
});
Expand All @@ -38,11 +44,12 @@ bot.init = function(cb) {
fs.mkdirSync("./"+bot[i]);
}
});
log.level(bot.config.logLevel);
cb(null);
};

bot.initModuleManager = function(cb) {
moduleMan.init(bot, cb);
moduleMan.init(bot, log, cb);
};

var supportedConfigTypes = [
Expand Down Expand Up @@ -109,7 +116,7 @@ bot.loadConfig = function(cb) { //sync
try {
conf = JSON.parse(fs.readFileSync('./config.json'));
} catch(ex) {
console.log("Error reading config file: ", e);
log.error(e, "error reading config file");
conf = default_config;
}

Expand All @@ -120,15 +127,15 @@ bot.loadConfig = function(cb) { //sync
try {
conf[key] = JSON.parse(process.env[envKey]);
} catch(ex) {
console.log("Could not load key: " + envKey + " because it was not valid json");
log.error("could not load env config '%s' because it was not valid json", envKey);
}
}
});

var def_keys = Object.keys(default_config);
_.each(default_config, function(value, key) {
if(typeof conf[key] === 'undefined') {
console.log("Setting: ", key, " to ", value);
log.debug("defaulting %s=%s", key, value);
conf[key] = value;
}
});
Expand Down Expand Up @@ -157,21 +164,27 @@ bot.initClient = function(cb) {

var quoteSplit = new SnailEscape();

bot.client.on('error', function(err) { console.log(err);});
bot.client.on('error', function(err) {
log.error(err, "irc client error");
});


bot.client.on('join', function(channel, nick, raw) {
log.trace({channel: channel, nick: nick, raw: raw, event: "join"});
bot.callModuleFn('join', [channel, nick, raw]);
});
bot.client.on('part', function(channel, nick, raw) {
log.trace({channel: channel, nick: nick, raw: raw, event: "part"});
bot.callModuleFn('part', [channel, nick, raw]);
});
bot.client.on('quit', function(nick,reason,channels,raw) {
log.trace({channel: channel, nick: nick, reason: reason, raw: raw, event: "quit"});
bot.callModuleFn('quit', [nick, reason, channels, raw]);
});


bot.client.on('notice', function(from, to, text, raw) {
log.trace({from: from, to: to, text: text, raw: raw, event: "notice"});
var primaryFrom = (to == bot.client.nick) ? from : to;

bot.callModuleFn('notice', [text, from, to, bot.getNoticeReply(primaryFrom), raw]);
Expand All @@ -184,6 +197,7 @@ bot.initClient = function(cb) {
});

bot.client.on('message', function(from, to, text, raw) {
log.trace({from: from, to: to, text: text, raw: raw, event: "message"});
var primaryFrom = (to == bot.client.nick) ? from : to;
bot.callModuleFn('message', [text, from, to, bot.getReply(primaryFrom), raw]);

Expand All @@ -208,6 +222,7 @@ bot.initClient = function(cb) {
});

bot.client.on('ctcp', function(from, to, text, type, raw) {
log.trace({from: from, to: to, text: text, type: type, raw: raw, event: "ctcp"});
if(from == bot.config.owner && to == bot.client.nick && text == "RELOAD") {
moduleMan.reloadModules();
} else if(from == bot.config.owner && to == bot.client.nick && text == "LOAD") {
Expand All @@ -218,6 +233,7 @@ bot.initClient = function(cb) {
});

bot.client.on('action', function(from, to, text, type, raw) {
log.trace({from: from, to: to, text: text, type: type, raw: raw, event: "action"});
var primaryFrom = (to == bot.client.nick) ? from : to;
moduleMan.callModuleFn('action', [text, from, to, bot.getActionReply(primaryFrom), raw]);
if(to == bot.client.nick) {
Expand All @@ -231,6 +247,7 @@ bot.initClient = function(cb) {
// Note, this will not work if we send notices or certain other events,
// but that won't happen in practice yet
bot.client.on('selfMessage', function(to, text) {
log.trace({to: to, text: text, event: "selfMessage"});
// Hack! This ensures that even though node-irc calls this as part of the same function path, the events for pmsay/chansay happen a tick later.
// To understand why this matters, see issue
// https://github.com/euank/EuIrcBot/issues/131.
Expand Down Expand Up @@ -287,7 +304,9 @@ bot.say = function(args) {
};

bot.joinChannels = function(cb) {
if(!cb) cb = function(err) { if(err) console.log(err); };
if(!cb) cb = function(err) {
if(err) log.error(err);
};

var channels = Array.isArray(bot.conf.channels) ? bot.conf.channels : bot.conf.channels.split(',');
async.map(channels, function(item, joined) {
Expand Down Expand Up @@ -394,14 +413,17 @@ bot.fsListData = function(namespace, listPath, cb) {
bot.dump = function() {
if(heapdump) {
heapdump.writeSnapshot(function(err, filename) {
console.log('Heapdump written to', filename);
log.warn('heapdump written to', filename);
});
} else {
log.trace("dump called, but heapdump off");
}
}
};

async.series([
function(cb) {
bot.conf = bot.config = bot.loadConfig();
log.trace("loaded config");
cb(null);
},
bot.initClient,
Expand All @@ -410,7 +432,7 @@ async.series([
bot.client.connect(function(){cb(null);});
},
function(cb){
console.log("Connected!");
log.info("connected!");
cb(null);
},
bot.initModuleManager,
Expand All @@ -422,8 +444,8 @@ async.series([
], function(err, results) {
if(err) {
bot.dump();
console.trace("Error in init");
console.log(err);
log.fatal("error in init");
log.error(err);
}
});

Expand Down
3 changes: 2 additions & 1 deletion config.example.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
"realName": "seubot",
"server": "irc.freenode.net",
"owner": "owner",
"logLevel": "info",
"commandPrefix": "!",
"ssl": false,
"port": 6667,
Expand All @@ -18,7 +19,7 @@
"channelPrefixes": "&#",
"messageSplit": 512,
"moduleFolders": ["modules"],
"disabledModules": ["github"],
"disabledModules": ["github", "testlog"],
"datafolder": "data",
"tmpfolder": "tmp",
"configfolder": "conf"
Expand Down
34 changes: 34 additions & 0 deletions modules/testlog.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,34 @@
module.exports.name = "sirc-testlog";

module.exports.run_testlog = function(remainder, parts, reply, command, from, to, text, raw, regex) {
this.log.info(parts);
reply("logged at info");
};

module.exports.run_testlog2 = function(remainder, parts, reply, command, from, to, text, raw, regex) {
var self = this;
process.nextTick(function() {
self.log.info(parts);
reply("logged in a callback");
});
};

module.exports.run_testlog3 = function(remainder, parts, reply, command, from, to, text, raw, regex) {
process.nextTick(function() {
module.exports.log.info(parts);
reply("logged in a callback via module");
});
};


var l;
module.exports.init = function() {
l = this.log;
};

module.exports.run_testlog4 = function(remainder, parts, reply, command, from, to, text, raw, regex) {
process.nextTick(function() {
l.info(parts);
reply("logged in a callback via a module-scoped variable");
});
};
34 changes: 19 additions & 15 deletions node-module-manager.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,18 +1,21 @@
var fs = require('fs'),
path = require('path'),
async = require('async'),
_ = require('underscore');
_ = require('lodash'),
bunyan = require('bunyan');

var modules = {};
var modulePaths = {};

var config;
var bot;
var log;

var me = module.exports = {};

me.init = function(botObj, cb) {
me.init = function(botObj, logObj, cb) {
bot = botObj;
log = logObj;
config = botObj.config;
if(cb) cb(null);
};
Expand All @@ -31,8 +34,7 @@ me.getModuleName = function(mpath) {
m = JSON.parse(fs.readFileSync(path.join(mpath, 'package.json'))).name;
if(m) return m;
} catch(ex) {
console.log("Invalid package.json for " + mpath);
console.log(ex);
log.warn(ex, "invalid package.json for %s", mpath);
}
}
return mpath;
Expand All @@ -41,7 +43,7 @@ me.getModuleName = function(mpath) {
me.loadModuleFolder = function(folder, cb) {
fs.readdir(path.join('.',folder), function(err, mPaths) {
if(err) {
console.log(err);
log.warn(err, "error reading module folder: %s", folder);
// Don't err; it'll stop async from hitting up other module folders
return cb(null, {modules: {}, modulePaths: {}});
}
Expand All @@ -51,7 +53,7 @@ me.loadModuleFolder = function(folder, cb) {
/* ./ required because of how require works. go figure. */
var fullPath = './' + path.join('.', folder, mPaths[i]);
var moduleName = me.getModuleName(fullPath);
if(_.contains(config.disabledModules, moduleName)) {
if(_.includes(config.disabledModules, moduleName)) {
continue;
}
if(modules[moduleName]) continue;
Expand All @@ -61,8 +63,7 @@ me.loadModuleFolder = function(folder, cb) {
modules[moduleName] = mod;
modulePaths[moduleName] = fullPath;
} catch(ex) {
console.error(ex.stack);
console.error(ex);
log.error(ex, "error loading %s", folder);
}
}
cb(false, {modules: modules, modulePaths: modulePaths});
Expand All @@ -84,7 +85,12 @@ me.loadModules = function(cb) {

me.initModules = function(cb) {
// Todo, don't ever init if they're already initted
_.each(_.values(modules), function(mod) {
_.forEach(modules, function(mod, name) {
mod.log = bunyan.createLogger({
name: 'euircbot/' + name,
serializers: {err: bunyan.stdSerializers.err}
});
mod._name = name;
if(typeof mod.init == 'function') {
mod.init(me.modifyThisForModule(mod));
}
Expand Down Expand Up @@ -117,8 +123,7 @@ me.callModuleFn = function(fname, args) {
try {
m[fname].apply(bot, args);
} catch(ex) {
console.log(ex.stack);
console.log(ex);
log.warn({err: ex, func: fname, args: args}, "exception calling module function");
}
}
});
Expand Down Expand Up @@ -291,10 +296,8 @@ me.traverseCommandHierarchy = function(botObj, fnObj, args) {
me.modifyThisForModule = function(module) {
var obj = _.clone(bot);
obj.getAllCommandFns = me.getAllCommandFns();
obj.name = _.find(Object.keys(modules), function(mname) {
return modules[mname] === module;
});

obj.name = module._name;
obj.datadir = bot.getDataFolder(obj.name);

obj.appendDataFile = function(file, data, cb) {
Expand All @@ -318,6 +321,7 @@ me.modifyThisForModule = function(module) {
obj.modules = modules;

obj.module = module;
obj.log = module.log;
return obj;
};

Expand All @@ -336,7 +340,7 @@ me.callCommandFn = function(command, args) {
var call = function(ctx, args) {
try {
ctx.fn.apply(me.modifyThisForModule(ctx.module), args);
} catch(ex) { console.trace("Call Command: " + command + "\n" + ex.stack); console.log(ex); }
} catch(ex) { log.warn({err: ex, command: command, args: args}); }
};

// String functions
Expand Down
1 change: 1 addition & 0 deletions package.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
"main": "bot.js",
"dependencies": {
"async": "latest",
"bunyan": "^1.8.10",
"change-case": "^2.3.0",
"heapdump": "latest",
"irc": "^0.5.1",
Expand Down
Loading