From 6f72c3b73cf44c89c1dc98dc266ce604e9e4eb78 Mon Sep 17 00:00:00 2001 From: Elijah Lazkani Date: Sun, 10 Sep 2017 14:29:01 -0400 Subject: [PATCH] Added a semi-sane logging system across the board. --- boots/admin.py | 56 ++++++++++++++++++++++++++++++++++++----- boots/admin_commands.py | 10 ++++---- boots/boots.py | 7 +++--- boots/eightball.py | 23 ++++++++++++----- boots/robot.py | 11 ++++++-- 5 files changed, 85 insertions(+), 22 deletions(-) diff --git a/boots/admin.py b/boots/admin.py index 1a49af8..d2c43ea 100644 --- a/boots/admin.py +++ b/boots/admin.py @@ -21,12 +21,12 @@ class Admin: LIST = re.compile(r'^list.*$') def __init__(self, client: robot.Bot, config: str = None): + self.logger = logging.getLogger("boots.admin.Admin") + self.logger.debug("Initializing...") self.client = client self.config = config or "./config/admin.pkl" self.admins = {} self.services = {} - self.logger = logging.getLogger() - self.logger.debug("Initializing...") client.on("PRIVMSG")(self._handle) async def init(self) -> None: @@ -36,6 +36,7 @@ class Admin: :return: None """ + self.logger.debug("init() Loading config") await self.load_config() @staticmethod @@ -111,16 +112,19 @@ class Admin: :param config str: the path to the configuration :return: None """ + self.logger.debug("load_config() attempting to load configuration {}".format(config)) try: async with aiofiles.open(self.abspath(config or self.config), mode='rb') as f: _file = await f.read() try: self.admins = pickle.loads(_file) except pickle.PickleError: + self.logger.warn("load_config() failed to load configuration, creating a new one") self.admins = {} await self.add_admin("Admin", "Pa$$w0rd", 1000) f.close() except FileNotFoundError: + self.logger.warn("load_config() failed to read the configuration file, creating a new configuration") self.admins = {} await self.add_admin("Admin", "Pa$$w0rd", 1000) @@ -131,6 +135,7 @@ class Admin: :param config str: the path to the configuration :return: None """ + self.logger.debug("Attempting to write to drive...") async with aiofiles.open(self.abspath(config or self.config), mode='wb+') as f: _file = pickle.dumps(self.admins) await f.write(_file) @@ -146,6 +151,7 @@ class Admin: :param password str: the password to be added :return: None """ + self.logger.debug("add_admin() adding {}".format(user)) self.admins[user] = {} self.admins[user]['password'] = self.hash(password) self.admins[user]['level'] = level @@ -154,6 +160,7 @@ class Admin: self.admins[user]['logged_in_nick'] = None self.admins[user]['LOGIN'] = re.compile( r'^login\s+({})\s+({})\s*$'.format(user, re.escape(self.hash(password)))) + self.logger.debug("add_admin() calling save_config()") await self.save_config() async def rm_admin(self, user: str) -> None: @@ -166,7 +173,9 @@ class Admin: :param user str: the key user to delete from the list of admins :return: None """ + self.logger.debug("rm_admin() removing {}".format(user)) del self.admins[user] + self.logger.debug("rm_admin() calling save_config()") await self.save_config() async def _handle(self, nick: str, target: str, message: str, **kwargs: dict) -> None: @@ -180,11 +189,12 @@ class Admin: :param kwargs dict: for API compatibility :return: None """ - self.logger.debug("nick={} target={} message={}".format(nick, target, message)) - self.logger.debug("{}".format(kwargs)) + self.logger.debug("_handle() nick={} target={} message={} kwargs={}".format( + nick, target, message, kwargs)) # Set the admin flag admin = self.is_admin(nick, kwargs['host']) + self.logger.debug("_handle() check if {} is admin".format(nick)) if admin: kwargs['is_admin'] = True kwargs['level'] = self.admins[admin]['level'] @@ -193,6 +203,7 @@ class Admin: if kwargs.get('level', None) is not None: del kwargs['level'] + self.logger.debug("_handle() is parsing the message sent by {}".format(nick)) if self.HELP.match(message): self.admin_help(nick, target, message, **kwargs) elif self.LOGIN.match(message): @@ -208,10 +219,11 @@ class Admin: elif self.LIST.match(message): self.admin_list(nick, target, **kwargs) + self.logger.debug("_handle() is modifying kwargs") kwargs['nick'] = nick kwargs['target'] = target kwargs['message'] = message - + self.logger.debug("_handle() is trigger a new event called ADMIN with {}".format(kwargs)) self.client.trigger('ADMIN', **kwargs) def admin_help(self, nick: str, target: str, message: str, **kwargs: dict) -> None: @@ -235,6 +247,7 @@ class Admin: :return: None """ if target == self.client.nick: + self.logger.debug("admin_help() received a help request from {}".format(nick)) if kwargs.get("is_admin", None) is True: match_help = self.HELP.match(message) match_help_cmd = self.HELP_CMD.match(message) @@ -283,6 +296,7 @@ class Admin: :return: None """ if target == self.client.nick: + self.logger.debug("log_in() is called by {}".format(nick)) match = self.LOGIN.match(message) user = self.admins.get(match.group(1), None) if user: @@ -290,10 +304,13 @@ class Admin: if login.match(self.hash_pass(message)): if kwargs.get('is_admin', None) is True and \ match.group(1) != self.is_admin(nick, kwargs['host']): + self.logger.warn( + "log_in() {} already logged in as different user, logging him out".format(nick)) await self.log_out(nick, target, **kwargs) if match.group(1) == self.is_admin(nick, kwargs['host']): kwargs['target'] = nick kwargs['message'] = "{} you are already logged in...".format(nick) + self.logger.warn("log_in() {} already logged in, notifying".format(nick)) else: self.admins[match.group(1)]['logged_in'] = True self.admins[match.group(1)]['logged_in_nick'] = str(nick) @@ -302,8 +319,10 @@ class Admin: kwargs['target'] = nick kwargs['message'] = "{}, you are logged in to {} successfully".format( nick, match.group(1)) + self.logger.debug("log_in() {} has been logged in successfully, notifying".format(nick)) self.logger.debug("LOGIN from kwargs: {}".format(kwargs)) self.client.send("PRIVMSG", **kwargs) + self.logger.debug("log_in() is calling save_config()") await self.save_config() async def log_out(self, nick: str, target: str, **kwargs: dict) -> None: @@ -322,6 +341,7 @@ class Admin: :return: None """ if target == self.client.nick: + self.logger.debug("log_out() is being called by {}".format(nick)) if kwargs.get('is_admin', None) is True: admin = self.is_admin(nick, kwargs['host']) if admin: @@ -332,7 +352,9 @@ class Admin: kwargs['target'] = nick kwargs['message'] = "{}, you are logged out of {} successfully".format( nick, admin) + self.logger.debug("log_out() {} has been successfully logged out, notifying".format(nick)) self.client.send("PRIVMSG", **kwargs) + self.logger.debug("log_out() is calling save_config") await self.save_config() async def passwd(self, nick: str, target: str, message: str, **kwargs: dict) -> None: @@ -349,6 +371,7 @@ class Admin: :return: None """ if target == self.client.nick: + self.logger.debug("passwd() is being called by {}".format(nick)) if kwargs.get('is_admin', None) is True: match = self.PASSWD.match(message) if len(match.groups()) == 1: @@ -359,9 +382,12 @@ class Admin: kwargs['target'] = nick kwargs['message'] = '{}, password for {} has been successfully changed...'.format( nick, admin) + self.logger.debug("passwd() password for {} has been successfully changed, notifying".format(nick)) self.client.send("PRIVMSG", **kwargs) + self.logger.debug("passwd() is calling save_config()") await self.save_config() kwargs['target'] = self.client.nick + self.logger.debug("passwd() is logging {} out".format(nick)) await self.log_out(nick, **kwargs) async def admin_add(self, nick: str, target: str, message: str, **kwargs: dict) -> None: @@ -378,6 +404,7 @@ class Admin: :return: None """ if target == self.client.nick: + self.logger.debug("admin_add() is called by {}".format(nick)) if kwargs.get('is_admin', None) is True: match = self.ADD.match(message) if len(match.groups()) == 3: @@ -386,10 +413,15 @@ class Admin: level = self.level_up(kwargs['level'], int(match.group(3))) kwargs['message'] = "{} has been added with level {}...".format( match.group(1), level) + self.logger.debug( + "admin_add() admin {} has been added with level {}, notifying {}".format( + match.group(1), level, nick)) await self.add_admin(match.group(1), match.group(2), level) else: kwargs['target'] = nick kwargs['message'] = "{} has already been added...".format(match.group(1)) + self.logger.warn( + "admin_add() {} has already been added, notifying {}".format(match.group(1), nick)) self.client.send("PRIVMSG", **kwargs) async def admin_rm(self, nick: str, target: str, message: str, **kwags: dict) -> None: @@ -408,23 +440,30 @@ class Admin: :return: None """ if target == self.client.nick: + self.logger.debug("admin_rm() is being called by {}".format(nick)) if kwags.get('is_admin', None) is True: match = self.RM.match(message) if len(match.groups()) == 1: if self.admins.get(match.group(1), None) is None: kwags['target'] = nick kwags['message'] = "{} is not on the list...".format(match.group(1)) + self.logger.warn("admin_rm() ") else: if kwags['level'] > self.admins[match.group(1)]['level'] or \ (kwags['level'] == 1000 and self.admins[match.group(1)]['level'] and kwags['level'] == self.admins[match.group(1)]['level']): kwags['target'] = nick kwags['message'] = "{} has been removed...".format(match.group(1)) + self.logger.debug("admin_rm() admin {} has been removed, notifying {}".format( + match.group(1), nick)) await self.rm_admin(match.group(1)) else: kwags['target'] = nick kwags['message'] = "{}, you do not have enough access to delete {}".format( nick, match.group(1)) + self.logger.warn( + "admin_rm() {0} does not have enough access to delete {1}, notifying {0}".format( + nick, match.group(1))) self.client.send("PRIVMSG", **kwags) def admin_list(self, nick: str, target: str, **kwargs: dict) -> None: @@ -437,6 +476,7 @@ class Admin: :return: None """ if target == self.client.nick: + self.logger.debug("admin_list() is being called by {}".format(nick)) if kwargs.get('is_admin', None) is True: admins = "" for key, _ in self.admins.items(): @@ -448,6 +488,8 @@ class Admin: kwargs['message'] = "List of Administrators:" self.client.send("PRIVMSG", **kwargs) kwargs['message'] = admins + self.logger.debug("admin_list() is returning admin list page to user {}".format( + kwargs)) self.client.send("PRIVMSG", **kwargs) def is_admin(self, user: str, host: str): @@ -459,10 +501,12 @@ class Admin: :param host str: the host to check against :return str: account if admin in list of admins """ + self.logger.debug("is_admin() is being called for {}".format(user)) for admin, value in self.admins.items(): if value.get('logged_in', None) and \ value.get('logged_in_nick', None) == user and \ value.get('logged_in_hostname', None) == host: - self.logger.debug("{} is an admin".format(admin)) + self.logger.debug("is_admin() is returning {} as an admin".format(user)) return admin + self.logger.debug("is_admin() is returning nothing, {} is not an admin".format(user)) return None diff --git a/boots/admin_commands.py b/boots/admin_commands.py index 689cf59..a0b2512 100644 --- a/boots/admin_commands.py +++ b/boots/admin_commands.py @@ -12,30 +12,30 @@ class AdminCmd: into known actions defined by users """ def __init__(self, admin: admin.Admin, modifier: str = "!"): + self.logger = logging.getLogger("boots.admin_commands.AdminCmd") + self.logger.debug("Initializing...") self.admin = admin self.client = admin.client self.modifier = modifier self.modifier_pattern = r'^{}([^\s]+).*$'.format(modifier) self.services = {} - self.logger = logging.getLogger() - self.logger.debug("Initializing...") admin.client.on("ADMIN")(self._handle) - def _handle(self, target, message, **kwargs) -> None: + def _handle(self, target: str, message: str, **kwargs: dict) -> None: """ client callback on event trigger - :param nick str: the nickname of the caller :param target str: the target the message was sent to :param message str: the message sent to the target :param kwargs dict: for API compatibility :return: None """ if bool(kwargs.get('is_admin', None)): + self.logger.debug("_handle() is being called by {}".format(kwargs['nick'])) for regex, (func, pattern) in self.services.items(): match = regex.match(message) if match: - self.logger.debug("Calling the function that matched the regex {}".format(regex)) + self.logger.debug("_handle() calling the function that matched the regex {}".format(regex)) split_msg = message.split(" ") message = " ".join(split_msg[1:]) self.client.loop.create_task( diff --git a/boots/boots.py b/boots/boots.py index d9f7288..6f3fdb2 100644 --- a/boots/boots.py +++ b/boots/boots.py @@ -5,9 +5,10 @@ import eightball import admin import admin_commands -logging.basicConfig() -logger = logging.getLogger() -logger.setLevel(logging.DEBUG) +format = '%(asctime)s - %(name)s - %(levelname)s - %(message)s' +logging.basicConfig(level=logging.DEBUG, format=format) +logger = logging.getLogger('boots') + async def plugins(bot: robot.Bot): magic_ball = eightball.EightBall(bot) diff --git a/boots/eightball.py b/boots/eightball.py index 91ee9ca..831a149 100644 --- a/boots/eightball.py +++ b/boots/eightball.py @@ -34,11 +34,11 @@ class EightBall: ] def __init__(self, client: robot.Bot, keyword: str = ".8ball"): + self.logger = logging.getLogger("boots.eightball.Eightball") + self.logger.debug("Initializing...") self.client = client self.questions = {} self.keyword_pattern = r'^{}\s+(.+)$'.format(keyword) - self.logger = logging.getLogger() - self.logger.debug("Initializing...") client.on("PRIVMSG")(self._handle) def _handle(self, nick, target, message, **kwargs) -> None: @@ -51,7 +51,7 @@ class EightBall: :param kwargs dict: :return: None """ - + self.logger.debug("_handle() is being called by {}".format(nick)) nick, target = self._prefix(nick, target) # Check that it did not call itself @@ -62,11 +62,13 @@ class EightBall: match = regex.match(message) if match: if is_question(match.group(1)): - message = "{}, {}".format(nick, self._get_answer()) + answer = self._get_answer() + message = "{}, {}".format(nick, answer) + self.logger.debug("_handle() found '{}', notifying {}".format(answer, nick)) else: message = \ "{}, I did not detect a question for me to answer".format(nick) - self.logger.debug("PRIVMSG {}".format(message)) + self.logger.debug("_handle() did not detect a question, notifying {}".format(nick)) self.client.loop.create_task( func(target, message, **kwargs)) @@ -88,7 +90,12 @@ class EightBall: target = nick return nick, target - def _get_answer(self): + def _get_answer(self) -> str: + """ + This method will randomly return an answer + + :return: str a random answer + """ return random.choice(self.ANSWERS) def on_keyword(self, @@ -113,6 +120,7 @@ class EightBall: self.questions[compiled] = (wrapped, self.keyword_pattern) return func +logger = logging.getLogger("boots.eightball") def is_question(phrase: str) -> bool: """ @@ -121,7 +129,10 @@ def is_question(phrase: str) -> bool: :param phrase str: the phrase to check :return: bool if the phrase is a question or not """ + logger.debug("is_question() is being calling aganist '{}'".format(phrase)) compiled = re.compile(r'^[^\?]+\?\s*$') if compiled.match(phrase): + logger.debug("is_question() is returning True") return True + logger.debug("is_question() is returning False") return False diff --git a/boots/robot.py b/boots/robot.py index 16675db..6780e33 100644 --- a/boots/robot.py +++ b/boots/robot.py @@ -17,7 +17,8 @@ class Bot(bottom.Client): realname: str = None, channels: list = None) -> None: super().__init__(host=host, port=port, ssl=ssl) - self.logger = logging.getLogger() + self.logger = logging.getLogger("admin.robot.Bot") + self.logger.debug("Initializing...") self.nick = nick self.user = user or self.nick self.realname = realname or self.nick @@ -35,7 +36,7 @@ class Bot(bottom.Client): :return: None """ message = message or "" - self.logger.debug("PONG {}".format(message)) + self.logger.debug("keepalive() PONG {}".format(message)) self.send("pong", message=message) async def on_connect(self, **kwargs: dict) -> None: @@ -46,7 +47,10 @@ class Bot(bottom.Client): :param kwargs dict: for API compatibility :return: None """ + self.logger.debug("on_connect() is being called") + self.logger.debug("on_connect() is sending NICK as {} to server ".format(self.nick)) self.send('NICK', nick=self.nick) + self.logger.debug("on_connect() is sending USER {} {}".format(self.user, self.realname)) self.send('USER', user=self.user, realname=self.realname) @@ -60,9 +64,12 @@ class Bot(bottom.Client): # Cancel whichever waiter's event didn't come in for future in pending: future.cancel() + self.logger.debug("on_connect() is auto-joining channels {}".format(self.channels)) for channel in self.channels: self.send('JOIN', channel=channel) async def on_disconnect(self, **kwargs: dict) -> None: + self.logger.debug("on_disconnect() is being called") await self.disconnect() + self.logger.debug("on_disconnect() is calling loop.stop()") self.loop.stop()