Add 'trace' logging level for src/Database.py and src/EventManager.py very

verbose debugging

modules/print_activity.py

@@ -10,15 +10,12 @@ class Module(ModuleManager.BaseModule):
         self.bot.log.info("%s | %s", [target, line])
 
     def _on_message(self, event, nickname):
-        if not self.bot.args.verbose:
+        if event["action"]:
-            if event["action"]:
+            self.print_line(event, "* %s %s" % (nickname, event["message"]),
-                self.print_line(event, "* %s %s" % (
+                channel=event["channel"].name)
-                    nickname, event["message"]),
+        else:
-                    channel=event["channel"].name)
+            self.print_line(event, "<%s> %s" % (nickname, event["message"]),
-            else:
+                channel=event["channel"].name)
-                self.print_line(event, "<%s> %s" % (
-                    nickname, event["message"]),
-                    channel=event["channel"].name)
     @Utils.hook("received.message.channel",
         priority=EventManager.PRIORITY_HIGH)
     def channel_message(self, event):
@@ -42,9 +39,8 @@ class Module(ModuleManager.BaseModule):
         self.print_line(event, "(server notice) %s" % event["message"])
 
     def _on_join(self, event, nickname):
-        if not self.bot.args.verbose:
+        self.print_line(event, "%s joined %s" % (nickname,
-            self.print_line(event, "%s joined %s" % (nickname,
+            event["channel"].name))
-                event["channel"].name))
     @Utils.hook("received.join")
     def join(self, event):
         self._on_join(event, event["user"].nickname)
@@ -53,10 +49,10 @@ class Module(ModuleManager.BaseModule):
         self._on_join(event, event["server"].nickname)
 
     def _on_part(self, event, nickname):
-        if not self.bot.args.verbose:
+        self.print_line(event, "%s left %s%s" % (
-            self.print_line(event, "%s left %s%s" % (nickname,
+            nickname,
-                event["channel"].name, "" if not event[
+            event["channel"].name,
-                "reason"] else " (%s)" % event["reason"]))
+            "" if not event["reason"] else " (%s)" % event["reason"]))
     @Utils.hook("received.part")
     def part(self, event):
         self._on_part(event, event["user"].nickname)
@@ -67,21 +63,18 @@ class Module(ModuleManager.BaseModule):
     @Utils.hook("received.nick")
     @Utils.hook("self.nick")
     def on_nick(self, event):
-        if not self.bot.args.verbose:
+        self.print_line(event, "%s changed nickname to %s" % (
-            self.print_line(event, "%s changed nickname to %s" % (
+            event["old_nickname"], event["new_nickname"]))
-                event["old_nickname"], event["new_nickname"]))
 
     @Utils.hook("received.quit")
     def on_quit(self, event):
-        if not self.bot.args.verbose:
+        self.print_line(event, "%s quit%s" % (event["user"].nickname,
-            self.print_line(event, "%s quit%s" % (event["user"].nickname,
+            "" if not event["reason"] else " (%s)" % event["reason"]))
-                "" if not event["reason"] else " (%s)" % event["reason"]))
 
     def _on_kick(self, event, nickname):
-        if not self.bot.args.verbose:
+        self.print_line(event, "%s kicked %s from %s%s" % (
-            self.print_line(event, "%s kicked %s from %s%s" % (
+            event["user"].nickname, nickname, event["channel"].name,
-                event["user"].nickname, nickname, event["channel"].name,
+            "" if not event["reason"] else " (%s)" % event["reason"]))
-                "" if not event["reason"] else " (%s)" % event["reason"]))
     @Utils.hook("received.kick")
     def kick(self, event):
         self._on_kick(event, event["target_user"].nickname)

src/Database.py

@@ -272,7 +272,7 @@ class Database(object):
 
     def _execute_fetch(self, query, fetch_func, params=[]):
         printable_query = " ".join(query.split())
-        self.log.debug("executing query: \"%s\" (params: %s)",
+        self.log.trace("executing query: \"%s\" (params: %s)",
             [printable_query, params])
         start = time.monotonic()
 
@@ -282,7 +282,7 @@ class Database(object):
 
         end = time.monotonic()
         total_milliseconds = (end - start) * 1000
-        self.log.debug("executed in %fms", [total_milliseconds])
+        self.log.trace("executed in %fms", [total_milliseconds])
 
         return value
     def execute_fetchall(self, query, params=[]):

src/EventManager.py

@@ -200,7 +200,7 @@ class EventHook(object):
         return self._call(kwargs, maximum=maximum)
     def _call(self, kwargs, maximum=None):
         event_path = self._get_path()
-        self.log.debug("calling event: \"%s\" (params: %s)",
+        self.log.trace("calling event: \"%s\" (params: %s)",
             [event_path, kwargs])
         start = time.monotonic()
 
@@ -217,7 +217,7 @@ class EventHook(object):
                     event_path], exc_info=True)
 
         total_milliseconds = (time.monotonic() - start) * 1000
-        self.log.debug("event \"%s\" called in %fms", [
+        self.log.trace("event \"%s\" called in %fms", [
             event_path, total_milliseconds])
 
         self.check_purge()

src/IRCBot.py

@@ -133,11 +133,7 @@ class Bot(object):
                     if event & select.EPOLLIN:
                         lines = server.read()
                         for line in lines:
-                            if self.args.verbose:
+                            self.log.debug("%s (raw) | %s", [str(server), line])
-                                self.log.info("<%s | %s", [str(server), line])
-                            else:
-                                self.log.debug("%s (raw) | %s", [str(server),
-                                    line])
                             server.parse_line(line)
                     elif event & select.EPOLLOUT:
                         server._send()

src/Logging.py

@@ -1,5 +1,14 @@
 import logging, logging.handlers, os, sys, time
 
+LEVELS = {
+    "trace": 5,
+    "debug": logging.DEBUG,
+    "info": logging.INFO,
+    "warn": logging.WARN,
+    "error": logging.ERROR,
+    "critical": logging.CRITICAL
+}
+
 class BitBotFormatter(logging.Formatter):
     def formatTime(self, record, datefmt=None):
         ct = self.converter(record.created)
@@ -14,9 +23,15 @@ class BitBotFormatter(logging.Formatter):
         return s
 
 class Log(object):
-    def __init__(self, location):
+    def __init__(self, level, location):
+        logging.addLevelName(LEVELS["trace"], "TRACE")
         self.logger = logging.getLogger(__name__)
-        self.logger.setLevel(logging.DEBUG)
+
+        if not level.lower() in LEVELS:
+            raise ValueError("Unknown log level '%s'" % level)
+        stdout_level = LEVELS[level.lower()]
+
+        self.logger.setLevel(LEVELS["trace"])
 
         formatter = BitBotFormatter(
             "%(asctime)s [%(levelname)s] %(message)s",
@@ -24,16 +39,18 @@ class Log(object):
         formatter.converter = time.gmtime
 
         stdout_handler = logging.StreamHandler(sys.stdout)
-        stdout_handler.setLevel(logging.INFO)
+        stdout_handler.setLevel(stdout_level)
         stdout_handler.setFormatter(formatter)
         self.logger.addHandler(stdout_handler)
 
         file_handler = logging.handlers.TimedRotatingFileHandler(
             location, when="midnight", backupCount=5)
-        file_handler.setLevel(logging.DEBUG)
+        file_handler.setLevel(LEVELS["trace"])
         file_handler.setFormatter(formatter)
         self.logger.addHandler(file_handler)
 
+    def trace(self, message, params, **kwargs):
+        self._log(message, params, LEVELS["trace"], kwargs)
     def debug(self, message, params, **kwargs):
         self._log(message, params, logging.DEBUG, kwargs)
     def info(self, message, params, **kwargs):

start.py

@@ -29,8 +29,8 @@ arg_parser.add_argument("--verbose", "-v", action="store_true")
 
 args = arg_parser.parse_args()
 
-
+log_level = "debug" if args.verbose else "info"
-log = Logging.Log(args.log)
+log = Logging.Log(log_level, args.log)
 cache = Cache.Cache()
 config = Config.Config(args.config)
 database = Database.Database(log, args.database)