Improved logging, added TRACE logging in Database.py to see how it performs

Database.py

@@ -1,7 +1,9 @@
-import json, os, sqlite3, threading
+
+import json, os, sqlite3, threading, time
 
 class Database(object):
     def __init__(self, bot, location="bot.db"):
+        self.bot = bot
         self.location = location
         self.full_location = os.path.join(bot.bot_directory,
             self.location)
@@ -21,9 +23,35 @@ class Database(object):
             self._cursor = self.database.cursor()
         return self._cursor
 
+    def _execute_fetch(self, query, fetch_func, params=[]):
+        printable_query = " ".join(query.split())
+        self.bot.events.on("log.debug").call(
+            message="executing query: \"%s\" (params: %s)",
+            params=[printable_query, params])
+        start = time.time()
+
+        cursor = self.cursor()
+        cursor.execute(query, params)
+        value = fetch_func(cursor)
+
+        end = time.time()
+        total_milliseconds = (end - start) * 1000
+        self.bot.events.on("log.debug").call(
+            message="executed in %fms",
+            params=[total_milliseconds])
+        return value
+    def execute_fetchall(self, query, params=[]):
+        return self._execute_fetch(query,
+            lambda cursor: cursor.fetchall(), params)
+    def execute_fetchone(self, query, params=[]):
+        return self._execute_fetch(query,
+            lambda cursor: cursor.fetchone(), params)
+    def execute(self, query, params=[]):
+        return self._execute_fetch(query, lambda cursor: None, params)
+
     def make_servers_table(self):
         try:
-            self.cursor().execute("""CREATE TABLE servers
+            self.execute("""CREATE TABLE servers
                 (server_id INTEGER PRIMARY KEY,
                 hostname TEXT, port INTEGER, password TEXT,
                 ipv4 BOOLEAN, tls BOOLEAN, nickname TEXT,
@@ -32,13 +60,13 @@ class Database(object):
             pass
     def make_bot_settings_table(self):
         try:
-            self.cursor().execute("""CREATE TABLE bot_settings
+            self.execute("""CREATE TABLE bot_settings
                 (setting TEXT PRIMARY KEY, value TEXT)""")
         except sqlite3.Error as e:
             pass
     def make_server_settings_table(self):
         try:
-            self.cursor().execute("""CREATE TABLE server_settings
+            self.execute("""CREATE TABLE server_settings
                 (server_id INTEGER, setting TEXT, value TEXT,
                 FOREIGN KEY(server_id) REFERENCES
                 servers(server_id) ON DELETE CASCADE,
@@ -47,7 +75,7 @@ class Database(object):
             pass
     def make_channel_settings_table(self):
         try:
-            self.cursor().execute("""CREATE TABLE channel_settings
+            self.execute("""CREATE TABLE channel_settings
                 (server_id INTEGER, channel TEXT, setting TEXT,
                 value TEXT, FOREIGN KEY (server_id) REFERENCES
                 servers(server_id) ON DELETE CASCADE,
@@ -56,7 +84,7 @@ class Database(object):
             pass
     def make_user_settings_table(self):
         try:
-            self.cursor().execute("""CREATE TABLE user_settings
+            self.execute("""CREATE TABLE user_settings
                 (server_id INTEGER, nickname TEXT, setting TEXT,
                 value TEXT, FOREIGN KEY (server_id) REFERENCES
                 servers(server_id) ON DELETE CASCADE,
@@ -65,19 +93,20 @@ class Database(object):
             pass
 
     def set_bot_setting(self, setting, value):
-        self.cursor().execute("""INSERT OR REPLACE INTO bot_settings
+        self.execute(
-            VALUES (?, ?)""", [setting.lower(), json.dumps(value)])
+            "INSERT OR REPLACE INTO bot_settings VALUES (?, ?)",
+            [setting.lower(), json.dumps(value)])
     def get_bot_setting(self, setting, default=None):
-        self.cursor().execute("""SELECT value FROM bot_settings
+        value = self.execute_fetchone(
-            WHERE setting=?""", [setting.lower()])
+            "SELECT value FROM bot_settings WHERE setting=?",
-        value = self.cursor().fetchone()
+            [setting.lower()])
         if value:
             return json.loads(value[0])
         return default
     def find_bot_settings(self, pattern, default=[]):
-        self.cursor().execute("""SELECT setting, value FROM bot_settings
+        values = self.execute_fetchall(
-            WHERE setting LIKE ?""", [pattern.lower()])
+            "SELECT setting, value FROM bot_settings WHERE setting LIKE ?",
-        values = self.cursor().fetchall()
+            [pattern.lower()])
         if values:
             for i, value in enumerate(values):
                 values[i] = value[0], json.loads(value[1])
@@ -86,26 +115,27 @@ class Database(object):
     def find_bot_settings_prefix(self, prefix, default=[]):
         return self.find_bot_settings("%s%" % prefix, default)
     def del_bot_setting(self, setting):
-        self.cursor().execute("""DELETE FROM bot_settings WHERE
+        self.execute(
-            setting=?""", [setting.lower()])
+            "DELETE FROM bot_settings WHERE setting=?",
+            [setting.lower()])
 
     def set_server_setting(self, server_id, setting, value):
-        self.cursor().execute("""INSERT OR REPLACE INTO server_settings
+        self.execute(
-            VALUES (?, ?, ?)""", [server_id, setting.lower(),
+            "INSERT OR REPLACE INTO server_settings VALUES (?, ?, ?)",
-            json.dumps(value)])
+            [server_id, setting.lower(), json.dumps(value)])
     def get_server_setting(self, server_id, setting, default=None):
-        self.cursor().execute("""SELECT value FROM server_settings
+        value = self.execute_fetchone(
-            WHERE server_id=? AND setting=?""", [server_id,
+            """SELECT value FROM server_settings WHERE
-            setting.lower()])
+            server_id=? AND setting=?""",
-        value = self.cursor().fetchone()
+            [server_id,setting.lower()])
         if value:
             return json.loads(value[0])
         return default
     def find_server_settings(self, server_id, pattern, default=[]):
-        self.cursor().execute("""SELECT setting, value FROM server_settings
+        values = self.execute_fetchall(
-            WHERE server_id=? AND setting LIKE ?""", [server_id,
+            """SELECT setting, value FROM server_settings WHERE
-            pattern.lower()])
+            server_id=? AND setting LIKE ?""",
-        values = self.cursor().fetchall()
+            [server_id, pattern.lower()])
         if values:
             for i, value in enumerate(values):
                 values[i] = value[0], json.loads(value[1])
@@ -114,26 +144,27 @@ class Database(object):
     def find_server_settings_prefix(self, server_id, prefix, default=[]):
         return self.find_server_settings(server_id, "%s%" % prefix, default)
     def del_server_setting(self, server_id, setting):
-        self.cursor().execute("""DELETE FROM server_settings WHERE
+        self.execute(
-            server_id=? AND setting=?""", [server_id, setting.lower()])
+            "DELETE FROM server_settings WHERE server_id=? AND setting=?",
+            [server_id, setting.lower()])
 
     def set_channel_setting(self, server_id, channel, setting, value):
-        self.cursor().execute("""INSERT OR REPLACE INTO channel_settings
+        self.execute(
-            VALUES (?, ?, ?, ?)""", [server_id, channel.lower(),
+            "INSERT OR REPLACE INTO channel_settings VALUES (?, ?, ?, ?)",
-            setting.lower(), json.dumps(value)])
+            [server_id, channel.lower(), setting.lower(), json.dumps(value)])
     def get_channel_setting(self, server_id, channel, setting, default=None):
-        self.cursor().execute("""SELECT value FROM channel_settings
+        value = self.execute_fetchone(
-            WHERE server_id=? AND channel=? AND setting=?""",
+            """SELECT value FROM channel_settings WHERE
+            server_id=? AND channel=? AND setting=?""",
             [server_id, channel.lower(), setting.lower()])
-        value = self.cursor().fetchone()
         if value:
             return json.loads(value[0])
         return default
     def find_channel_settings(self, server_id, channel, pattern, default=[]):
-        self.cursor().execute("""SELECT setting, value FROM channel_settings
+        values = self.execute_fetchall(
-            WHERE server_id=? AND channel=? setting LIKE '?'""", [server_id,
+            """SELECT setting, value FROM channel_settings WHERE
-            channel.lower(), pattern.lower()])
+            server_id=? AND channel=? setting LIKE '?'""",
-        values = self.cursor().fetchall()
+            [server_id, channel.lower(), pattern.lower()])
         if values:
             for i, value in enumerate(values):
                 values[i] = value[0], json.loads(value[1])
@@ -144,37 +175,38 @@ class Database(object):
         return self.find_channel_settings(server_id, channel, "%s%" % prefix,
             default)
     def del_channel_setting(self, server_id, channel, setting):
-        self.cursor().execute("""DELETE FROM channel_settings WHERE
+        self.execute(
-            server_id=? AND channel=? AND setting=?""", [server_id,
+            """DELETE FROM channel_settings WHERE
-            channel.lower(), setting.lower()])
+            server_id=? AND channel=? AND setting=?""",
+            [server_id, channel.lower(), setting.lower()])
 
     def set_user_setting(self, server_id, nickname, setting, value):
-        self.cursor().execute("""INSERT OR REPLACE INTO user_settings
+        self.execute(
-            VALUES (?, ?, ?, ?)""", [server_id, nickname.lower(),
+            "INSERT OR REPLACE INTO user_settings VALUES (?, ?, ?, ?)",
-            setting.lower(), json.dumps(value)])
+            [server_id, nickname.lower(), setting.lower(), json.dumps(value)])
     def get_user_setting(self, server_id, nickname, setting, default=None):
-        self.cursor().execute("""SELECT value FROM user_settings
+        value = self.execute_fetchone(
-            WHERE server_id=? AND nickname=? and setting=?""",
+            """SELECT value FROM user_settings WHERE
+            server_id=? AND nickname=? and setting=?""",
             [server_id, nickname.lower(), setting.lower()])
-        value = self.cursor().fetchone()
         if value:
             return json.loads(value[0])
         return default
     def get_all_user_settings(self, server_id, setting, default=[]):
-        self.cursor().execute("""SELECT nickname, setting, value FROM
+        values = self.execute_fetchall(
-            user_settings WHERE server_id=? AND setting=?""",
+            """SELECT nickname, setting, value FROM user_settings WHERE
+            server_id=? AND setting=?""",
             [server_id, setting])
-        values = self.cursor().fetchall()
         if values:
             for i, value in enumerate(values):
                 values[i] = value[0], value[1], json.loads(value[2])
             return values
         return default
     def find_user_settings(self, server_id, nickname, pattern, default=[]):
-        self.cursor().execute("""SELECT setting, value FROM user_settings
+        values = self.cursor().execute(
-            WHERE server_id=? AND nickname=? AND setting LIKE '?'""",
+            """SELECT setting, value FROM user_settings WHERE
+            server_id=? AND nickname=? AND setting LIKE '?'""",
             [server_id, nickname.lower(), pattern.lower()])
-        values = self.cursor().fetchall()
         if values:
             for i, value in enumerate(values):
                 values[i] = value[0], json.loads(value[1])
@@ -185,24 +217,27 @@ class Database(object):
         return self.find_user_settings(server_id, nickname, "%s%" % prefix,
             default)
     def del_user_setting(self, server_id, nickname, setting):
-        self.cursor().execute("""DELETE FROM user_settings WHERE
+        self.execute(
-            server_id=? AND nickname=? AND setting=?""", [server_id,
+            """DELETE FROM user_settings WHERE
-            nickname.lower(), setting.lower()])
+            server_id=? AND nickname=? AND setting=?""",
+            [server_id, nickname.lower(), setting.lower()])
 
     def add_server(self, hostname, port, password, ipv4, tls, nickname,
             username=None, realname=None):
         username = username or nickname
         realname = realname or nickname
-        self.cursor().execute("""INSERT INTO servers (hostname, port,
+        self.execute(
-            password, ipv4, tls, nickname, username, realname) VALUES (
+            """INSERT INTO servers (hostname, port, password, ipv4,
-            ?, ?, ?, ?, ?, ?, ?, ?)""", [hostname, port, password, ipv4,
+            tls, nickname, username, realname) VALUES (
-            tls, nickname, username, realname])
+            ?, ?, ?, ?, ?, ?, ?, ?)""",
+            [hostname, port, password, ipv4, tls, nickname, username, realname])
     def get_servers(self):
-        self.cursor().execute("""SELECT server_id, hostname, port, password,
+        return self.execute_fetchall(
-            ipv4, tls, nickname, username, realname FROM servers""")
+            """SELECT server_id, hostname, port, password, ipv4,
-        return self.cursor().fetchall()
+            tls, nickname, username, realname FROM servers""")
     def get_server(self, id):
-        self.cursor().execute("""SELECT server_id, hostname, port, password,
+        return self.execute_fetchone(
-            ipv4, tls, nickname, username, realname FROM servers WHERE
+            """SELECT server_id, hostname, port, password, ipv4,
-            server_id=?""", [id])
+            tls, nickname, username, realname FROM servers WHERE
-        return self.cursor().fetchone()
+            server_id=?""",
+            [id])

modules/logging.py

@@ -0,0 +1,38 @@
+import logging, sys
+
+class Module(object):
+    def __init__(self, bot):
+        self.logger = logging.getLogger(__name__)
+        self.logger.setLevel(logging.DEBUG)
+
+        formatter = logging.Formatter(
+            "%(asctime)s - %(levelname)s - %(message)s",
+            "%Y-%m-%dT%H:%M:%S%z")
+
+        stdout_handler = logging.StreamHandler(sys.stdout)
+        stdout_handler.setLevel(logging.INFO)
+        stdout_handler.setFormatter(formatter)
+        self.logger.addHandler(stdout_handler)
+
+        file_handler = logging.FileHandler('bot.log')
+        file_handler.setLevel(logging.DEBUG)
+        file_handler.setFormatter(formatter)
+        self.logger.addHandler(file_handler)
+
+        bot.events.on("log.debug").hook(self.debug)
+        bot.events.on("log.info").hook(self.info)
+        bot.events.on("log.warn").hook(self.warn)
+        bot.events.on("log.error").hook(self.error)
+
+    def debug(self, event):
+        self._log(event, logging.DEBUG)
+    def info(self, event):
+        self._log(event, logging.INFO)
+    def warn(self, event):
+        self._log(event, logging.WARN)
+    def error(self, event):
+        self._log(event, logging.ERROR)
+    def _log(self, event, level):
+        message = event["message"]
+        params = event.get("params", [])
+        self.logger.log(level, message, *params)

modules/logs.py

@@ -1,19 +0,0 @@
-import datetime
-
-class Module(object):
-    def __init__(self, bot):
-        bot.events.on("log").on("info", "warn", "error").hook(self.log)
-
-    def timestamp(self):
-        return datetime.datetime.utcnow().isoformat()+"Z"
-
-    def log(self, event):
-        log_level = event.name
-        timestamp = self.timestamp()
-        message = event["message"]
-        data = event.get("data")
-        with open("bot.log", "a") as log_file:
-            log_file.write("%s [%s] %s\n" % (timestamp, log_level,
-                message))
-            if data:
-                log_file.write("%s\n" % data)

modules/print_activity.py

@@ -36,7 +36,9 @@ class Module(object):
         target = str(event["server"])
         if not channel == None:
             target += channel
-        print("[%s] %s | %s" % (timestamp, target, line))
+        self.bot.events.on("log.info").call(
+            message="%s | %s",
+            params=[target, line])
 
     def _on_message(self, event, nickname):
         if not self.bot.args.verbose: