Add logging (#17)

* add console and file logging

* fix issues with starting logging, and now sends to plugins

* add option to turn off logging

* add more logging messages

* add various logging messages

* add logging messages lost in merge

examples/plugins/test.py

@@ -2,5 +2,6 @@ import pinhook.plugin
 
 @pinhook.plugin.register('!test')
 def test(msg):
+    msg.logger.info('This is test log output')
     return pinhook.plugin.message("{}: Test".format(msg.nick))
 

pinhook/bot.py

@@ -1,4 +1,5 @@
 import imp
+import logging
 import os
 import ssl
 import time
@@ -11,12 +12,13 @@ irc.client.ServerConnection.buffer_class.errors = 'replace'
 
 
 class Message:
-    def __init__(self, channel, nick, botnick, ops, cmd=None, arg=None, text=None, nick_list=None):
+    def __init__(self, channel, nick, botnick, ops, logger, cmd=None, arg=None, text=None, nick_list=None):
         self.channel = channel
         self.nick = nick
         self.nick_list = nick_list
         self.botnick = botnick
         self.ops = ops
+        self.logger = logger
         if cmd:
             self.cmd = cmd
         if arg:
@@ -37,6 +39,7 @@ class Bot(irc.bot.SingleServerIRCBot):
             irc.bot.SingleServerIRCBot.__init__(self, [(server, self.port)], nickname, nickname)
         self.chanlist = channels
         self.bot_nick = nickname
+        self.start_logging(self.log_level)
         self.load_plugins()
 
     def set_kwargs(self, **kwargs):
@@ -47,6 +50,7 @@ class Bot(irc.bot.SingleServerIRCBot):
             'ssl_required': False,
             'ns_pass': None,
             'nickserv': 'NickServ',
+            'log_level': 'info',
         }
         for k, v in kwargs.items():
             setattr(self, k, v)
@@ -54,33 +58,68 @@ class Bot(irc.bot.SingleServerIRCBot):
             if a not in kwargs:
                 setattr(self, a, kwarguments[a])
 
+    def start_logging(self, level):
+        if level == 'error':
+            level = logging.ERROR
+        elif level == 'warning':
+            level = logging.WARNING
+        elif level == 'info':
+            level = logging.INFO
+        elif level == 'debug':
+            level = logging.DEBUG
+        self.logger = logging.getLogger(self.bot_nick)
+        formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(module)s - %(message)s')
+        # Set console logger
+        ch = logging.StreamHandler()
+        ch.setFormatter(formatter)
+        # Set file logger
+        fh = logging.FileHandler('{}.log'.format(self.bot_nick))
+        fh.setFormatter(formatter)
+        # Set levels
+        if level != "off":
+            self.logger.setLevel(level)
+            ch.setLevel(level)
+            fh.setLevel(level)
+        # Add handlers
+        self.logger.addHandler(ch)
+        self.logger.addHandler(fh)
+        self.logger.info('Logging started!')
+
     def load_plugins(self):
         # clear plugin list to ensure no old plugins remain
+        self.logger.info('clearing plugin cache')
         pinhook.plugin.clear_plugins()
         # ensure plugin folder exists
+        self.logger.info('checking plugin directory')
         if not os.path.exists(self.plugin_dir):
+            self.logger.info('plugin directory {} not found, creating'.format(self.plugin_dir))
             os.makedirs(self.plugin_dir)
         # load all plugins
         for m in os.listdir(self.plugin_dir):
             if m.endswith('.py'):
                 try:
                     name = m[:-3]
+                    self.logger.info('loading plugin {}'.format(name))
                     fp, pathname, description = imp.find_module(name, [self.plugin_dir])
                     imp.load_module(name, fp, pathname, description)
                 except Exception as e:
-                    print(e)
+                    self.logger.exception('could not load plugin')
         # gather all commands and listeners
         self.cmds = {}
         self.lstnrs = {}
         for cmd in pinhook.plugin.cmds:
+            self.logger.debug('adding command {}'.format(cmd['cmd']))
             self.cmds[cmd['cmd']] = cmd['func']
         for lstnr in pinhook.plugin.lstnrs:
+            self.logger.debug('adding listener {}'.format(lstnr['lisn']))
             self.lstnrs[lstnr['lstn']] = lstnr['func']
 
     def on_welcome(self, c, e):
         if self.ns_pass:
+            self.logger.info('identifying with nickserv')
             c.privmsg(self.nickserv, 'identify {}'.format(self.ns_pass))
         for channel in self.chanlist:
+            self.logger.info('joining channel {}'.format(channel))
             c.join(channel)
 
     def on_pubmsg(self, c, e):
@@ -97,15 +136,20 @@ class Bot(irc.bot.SingleServerIRCBot):
         else:
             chan = e.target
         cmd = text.split(' ')[0]
+        self.logger.debug(
+            'Message info: channel: {}, nick: {}, cmd: {}, text: {}'.format(chan, nick, cmd, text)
+        )
         if len(text.split(' ')) > 1:
             arg = ''.join([i + ' ' for i in text.split(' ')[1:]]).strip()
         else:
             arg = ''
         output = None
         if cmd == '!join' and nick in self.ops:
+            self.logger.info('joining {} per request of {}'.format(arg, nick))
             c.join(arg)
             c.privmsg(chan, '{}: joined {}'.format(nick, arg))
         elif cmd == '!quit' and nick in self.ops:
+            self.logger.info('quitting per request of {}'.format(nick))
             c.quit("See y'all later!")
             quit()
         elif cmd == '!help':
@@ -113,6 +157,7 @@ class Bot(irc.bot.SingleServerIRCBot):
             msg = ', '.join(helplist)
             c.privmsg(chan, 'Available commands: {}'.format(msg))
         elif cmd == '!reload' and nick in self.ops:
+            self.logger.info('reloading plugins per request of {}'.format(nick))
             self.load_plugins()
             c.privmsg(chan, 'Plugins reloaded')
         elif cmd in self.cmds:
@@ -124,12 +169,13 @@ class Bot(irc.bot.SingleServerIRCBot):
                     nick=nick,
                     arg=arg,
                     botnick=self.bot_nick,
-                    ops=self.ops
+                    ops=self.ops,
+                    logger=self.logger
                 ))
                 if output:
                     self.process_output(c, chan, output)
             except Exception as e:
-                print(e)
+                self.logger.exception('issue with command {}'.format(cmd))
         else:
             for lstnr in self.lstnrs:
                 try:
@@ -139,17 +185,20 @@ class Bot(irc.bot.SingleServerIRCBot):
                         nick_list=list(self.channels[chan].users()),
                         nick=nick,
                         botnick=self.bot_nick,
-                        ops=self.ops
+                        ops=self.ops,
+                        logger=self.logger
                     ))
                     if output:
                         self.process_output(c, chan, output)
                 except Exception as e:
-                    print(e)
+                    self.logger.exception('issue with listener {}'.format(lstnr))
 
     def process_output(self, c, chan, output):
         for msg in output.msg:
             if output.msg_type == 'message':
+                self.logger.debug('output message: {}'.format(msg))
                 c.privmsg(chan, msg)
             elif output.msg_type == 'action':
+                self.logger.debut('output action: {}'.format(msg))
                 c.action(chan, msg)
             time.sleep(.5)