📝 Implement intensive logging into the project.

bot/__init__.py

@@ -5,9 +5,15 @@
 from bot import models, trello, messages, trello_wh
 from bot.base_bot import BaseBot, Context, Dialog
 
-logging.basicConfig(
-    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
-    level=logging.INFO)
+logger = logging.getLogger(__name__)
+
+
+def user_display(user):
+    return "{}:{}".format(user.id, user.username)
+
+
+def chat_display(chat):
+    return "chat:{}".format(chat.id)
 
 
 class AddHookDialog(Dialog):
@@ -86,6 +92,11 @@ def cancel(self, ctx: Context):
 def require_auth(fn):
     def wrapper(self, ctx, *args, **kwargs):
         if not ctx.session.trello_token:
+            logger.info(
+                "{user} attempted to run command {name} in {chat} unauthorized".format(
+                    user=user_display(ctx.message.from_user),
+                    chat=chat_display(ctx.message.chat),
+                    name=fn.__name__))
             ctx.send_message(messages.MUST_AUTH)
             return
         fn(self, ctx, *args, **kwargs)
@@ -97,6 +108,11 @@ def wrapper(self, ctx, *args, **kwargs):
 def require_admin(fn):
     def wrapper(self, ctx, *args, **kwargs):
         if ctx.session.admin_id != ctx.message.from_user.id:
+            logger.info(
+                "{user} attempted to run command {name} in {chat} being non-admin".format(
+                    user=user_display(ctx.message.from_user),
+                    chat=chat_display(ctx.message.chat),
+                    name=fn.__name__))
             ctx.send_message(messages.FORBIDDEN)
             return
         fn(self, ctx, *args, **kwargs)
@@ -107,17 +123,32 @@ def wrapper(self, ctx, *args, **kwargs):
 
 class TrelloBot(BaseBot):
     def __init__(self, telegram_key: str, trello_key: trello.App):
+        logger.debug("Create new instance of TrelloBot.")
+        logger.debug("...Init BaseBot.")
         super().__init__(telegram_key)
 
+        logger.debug("...Init trello.App.")
         self.trello_app = trello.App(trello_key)
 
+        logger.debug("...Init trello_wh.WebhookReciever.")
         self.wh_reciever = trello_wh.WebhookReciever(
             self, config.TRELLO_WH_HOST, config.TRELLO_WH_PORT)
 
     def run(self):
+        logger.info("Run the TrelloBot.")
+        logger.debug("...Start WebhookReciever.")
         self.wh_reciever.start()
+        logger.debug("...Run the BaseBot.")
         super().run()
 
+    def send_message(self, chat_id: int, text: str, *args, **kwargs):
+        try:
+            super().send_message(chat_id, text, *args, **kwargs)
+        except Exception as e:
+            logger.error(
+                "Message sending to chat id {} failed: {}. Message text: {}; other params: {}, {}.".format(
+                    chat_id, repr(e), repr(text), repr(args), repr(kwargs)))
+
     def wrap_context(self, ctx: Context):
         (ctx.session, _) = models.Session.get_or_create(chat_id=ctx.chat_id)
 
@@ -126,16 +157,39 @@ def wrap_context(self, ctx: Context):
 
         return ctx
 
+    def _log_command(self, ctx: Context, cmdname: str):
+        message = "/{cmdname} command was issued by {user} in {chat}"
+        logger.info(message.format(
+            cmdname=cmdname,
+            user=user_display(ctx.message.from_user),
+            chat=chat_display(ctx.message.chat)))
+
+    def _start_dialog_logged(self, ctx: Context, dialog: Dialog):
+        logger.info("Start dialog {dialog} with {user} in {chat}.".format(
+            dialog=type(dialog).__name__,
+            user=user_display(ctx.message.from_user),
+            chat=chat_display(ctx.message.chat)))
+        ctx.start_dialog(dialog)
+
     def cmd_start(self, ctx: Context):
+        self._log_command(ctx, "start")
         ctx.send_message(messages.START)
 
     def _cmd_auth_with_token(self, ctx: Context, token: str):
+        logger.debug("...Run auth with a token.")
+
+        logger.debug("...Retrieve account's information with token.")
         try:
             me = self.trello_app.session(token).members.me()
-        except trello.AuthError:
+        except trello.AuthError as e:
+            logger.error("Could not authorize with a token: " + repr(e))
             ctx.send_message(messages.AUTH_FAILURE)
             return
 
+        logger.info("...Authorized as '{}'.".format(me.fullname))
+        logger.debug("...Set {user} admin the {chat}".format(
+            user=user_display(ctx.message.from_user),
+            chat=chat_display(ctx.message.chat)))
         ctx.session.trello_token = token
         ctx.session.admin_id = ctx.message.from_user.id
         ctx.session.save()
@@ -144,27 +198,38 @@ def _cmd_auth_with_token(self, ctx: Context, token: str):
         ctx.send_message(msg)
 
     def _cmd_auth_group(self, ctx: Context):
+        logger.debug("...Run auth within a group.")
         try:
+            logger.debug("...Try to retrieve private session's trello token.")
             private_session = models.Session.get(chat_id=ctx.message.from_user.id)
 
             if not private_session.trello_token:
                 raise PermissionError('no token')
 
+            logger.debug("...Try to retrieve account info using found token.")
             trello_session = self.trello_app.session(private_session.trello_token)
             me = trello_session.members.me()
 
+            logger.info("...Authorized as '{}'.".format(me.fullname))
+            logger.debug("...Set {user} admin the {chat}".format(
+                user=user_display(ctx.message.from_user),
+                chat=chat_display(ctx.message.chat)))
             ctx.session.trello_token = private_session.trello_token
             ctx.session.admin_id = ctx.message.from_user.id
             ctx.session.save()
 
             msg = messages.AUTH_SUCCESS.format(fullname=me.fullname)
             ctx.send_message(msg)
 
-        except (models.Session.DoesNotExist, PermissionError, trello.AuthError):
+        except (models.Session.DoesNotExist, PermissionError, trello.AuthError) as e:
+            logger.info("...Private session not authorized: " + repr(e))
             ctx.send_message(messages.AUTH_GO_PRIVATE)
 
     def cmd_auth(self, ctx: Context):
+        self._log_command(ctx, "auth")
+
         if ctx.session.trello_token:
+            logger.debug("...Already authorized.")
             ctx.send_message(messages.AUTH_ALREADY)
             return
 
@@ -175,21 +240,29 @@ def cmd_auth(self, ctx: Context):
         try:
             self._cmd_auth_with_token(ctx, ctx.args[0])
             return
-        except IndexError:
+        except IndexError as e:
+            logger.debug("...Auth with token failed: " + repr(e))
             pass
 
+        logger.debug("...Return auth url.")
         msg = messages.AUTH_URL.format(url=self.trello_app.auth_url())
         ctx.send_message(msg)
 
 
     @require_auth
     def cmd_status(self, ctx: Context):
+        self._log_command(ctx, "status")
+
         try:
+            logger.debug("...Try to retrieve account info.")
             me = ctx.trello_session.members.me()
-        except trello.AuthError:
+        except trello.AuthError as e:
+            logger.info("...Command failed: " + repr(e))
             ctx.send_message(messages.STATUS_INVALID_TOKEN)
             return
 
+        logger.debug("...Retrieve admin of {chat}.".format(
+            chat=chat_display(ctx.message.chat)))
         admin = ctx.bot.get_chat(ctx.session.admin_id)
 
         msg = messages.STATUS_OK.format(fullname=me.fullname,
@@ -199,47 +272,76 @@ def cmd_status(self, ctx: Context):
     @require_auth
     @require_admin
     def cmd_unauth(self, ctx: Context):
+        self._log_command(ctx, "unauth")
+
+        logger.debug("...Delete board hooks.")
         models.BoardHook.delete().where(
             models.BoardHook.session == ctx.session).execute()
+        logger.debug("...Delete chat session.")
         ctx.session.delete_instance()
         ctx.send_message(messages.UNAUTH_SUCCESS)
 
     @require_auth
     @require_admin
     def cmd_notify(self, ctx: Context):
+        self._log_command(ctx, "notify")
+
         boards = ctx.trello_session.members.me().boards(filter='open')
-        ctx.start_dialog(AddHookDialog(boards))
+        logger.debug("...Found {} boards.".format(len(boards)))
+        self._start_dialog_logged(ctx, AddHookDialog(boards))
 
     @require_auth
     def cmd_list(self, ctx: Context):
+        self._log_command(ctx, "list")
+
         hooks = ctx.session.hooks.execute()
+        logger.debug("...Found {} hooks.".format(len(hooks)))
 
         hooks_msgs = []
         for h in hooks:
             try:
                 b = ctx.trello_session.boards.get(h.board_id)
                 bname = b.name
             except trello.NotFoundError:
+                logger.warn(
+                    "...Could not load board {} for hook {}. Deleting it.".format(
+                        h.board_id, h.id))
                 h.delete()
+                continue
 
             msg = messages.LIST_ITEM.format(board=bname)
             hooks_msgs.append(msg)
 
+        logger.debug(
+            "...Formed {} hook item messages.".format(len(hooks_msgs)))
         msg = messages.LIST.format(list='\n'.join(hooks_msgs))
         ctx.send_message(msg)
 
     @require_auth
     @require_admin
     def cmd_forget(self, ctx: Context):
+        self._log_command(ctx, "forget")
+
         hooks = ctx.session.hooks.execute()
+        logger.debug("...Found {} hooks.".format(len(hooks)))
+
         hook_map = {}
         for h in hooks:
-            b = ctx.trello_session.boards.get(h.board_id)
+            try:
+                b = ctx.trello_session.boards.get(h.board_id)
+            except trello.NotFoundError:
+                logger.warn(
+                    "...Could not load board {} for hook {}. Deleting it.".format(
+                        h.board_id, h.id))
+                h.delete()
+                continue
+
             hook_map[b.name] = h
 
-        ctx.start_dialog(ForgetHookDialog(hook_map))
+        ctx._start_dialog_logged(ctx, ForgetHookDialog(hook_map))
 
     def cmd_dev(self, ctx: Context):
+        self._log_command(ctx, "dev")
         msg = messages.DEV.format(
             session_id=ctx.session.chat_id,
             sender_id=ctx.message.from_user.id,
@@ -248,4 +350,5 @@ def cmd_dev(self, ctx: Context):
         ctx.send_message(msg)
 
     def cmd_help(self, ctx: Context):
+        self._log_command(ctx, "help")
         ctx.send_message(messages.HELP)

bot/trello_wh.py

@@ -1,4 +1,5 @@
 import time
+import logging
 from contextlib import contextmanager
 from datetime import datetime, timedelta
 from multiprocessing import Process
@@ -11,6 +12,8 @@
 from bot.models import BoardHook, Session
 
 app = Flask(__name__)
+logger = logging.getLogger(__name__)
+
 
 class MessageQueue:
 
@@ -175,21 +178,25 @@ def get_message_queue(self, chat_id, board):
         return chat_queues[board.id]
 
     def webhook_update(self, chat_id):
+        logger.info("Webhook update, chat id {}.".format(chat_id))
         if request.method == 'HEAD':
             return "OK"
 
         try:
             session = Session.get(Session.chat_id == chat_id)
         except Session.DoesNotExist:
+            logger.error("No session was found for chat_id {}.".format(chat_id))
             abort(404, 'No session with that chat id is found')
 
         data = request.json
         if not data:
+            logger.error("No json was found in update of chat_id {}.".format(chat_id))
             abort(400, 'Request must contain json data')
 
         try:
             id_model = data["model"]["id"]
         except (KeyError, TypeError):
+            logger.error("No .model.id field was found in update of chat_id {}.".format(chat_id))
             abort(400, '.model.id field is required')
 
         for h in session.hooks:
@@ -200,13 +207,17 @@ def webhook_update(self, chat_id):
             # Trello will automatically delete the webhook,
             # when they recieve status 410.
             # Source: https://developers.trello.com/apis/webhooks
+            logger.error("No webhook was found for update of chat_id {}.".format(chat_id))
             abort(410, 'Such hook does not exist')
 
         trello_session = self.app.session(session.trello_token)
 
         try:
             action = trello.Action.from_dict(trello_session, data['action'])
         except (KeyError, TypeError) as e:
+            logger.error(
+                "Could not parse action json in update for chat_id {}: {}.".format(
+                    chat_id, repr(e)))
             abort(400, '.action object is invalid')
 
         msg = self._action_to_msg(action)
@@ -220,6 +231,8 @@ def webhook_update(self, chat_id):
         return "OK"
 
     def start(self):
+        logger.info("Starting webhook receiver in host {}, port {}.".format(
+            self.host, self.port))
         self.flask_process = Process(target=self.flask.run,
                                      kwargs={'host': self.host, 'port': self.port})
         self.flask_process.start()
@@ -228,5 +241,6 @@ def stop(self):
         if not self.flask_process:
             return
 
+        logger.info("Stopping webhook receiver.")
         self.flask_process.terminate()
         self.flask_process = None

config.sample.py

@@ -4,6 +4,9 @@
 TRELLO_KEY = "<your trello api key>"
 
 DB_FILE = 'bot.sqlite'
+LOG_FILE = 'bot.log'
+# DEBUG, INFO, WARNING, ERROR or CRITICAL
+LOG_LEVEL = 'WARNING'
 
 TRELLO_WH_HOST = 'example.com'
 TRELLO_WH_PORT = 9099

main.py

@@ -1,5 +1,19 @@
 #!/usr/bin/env python3
+import logging
+
 import config
 from bot import TrelloBot
 
-TrelloBot(config.TELEGRAM_KEY, config.TRELLO_KEY).run()
+if hasattr(config, 'LOG_FILE') and hasattr(config, 'LOG_LEVEL'):
+    logging.basicConfig(
+        filename=config.LOG_FILE,
+        format="[{name}|{levelname}|{asctime}] {message}",
+        style='{',
+        datefmt="%Y-%m-%d %H:%M:%S",
+        level=getattr(logging, config.LOG_LEVEL.upper()))
+
+try:
+    TrelloBot(config.TELEGRAM_KEY, config.TRELLO_KEY).run()
+except Exception as e:
+    logging.critical("Could not start bot: {}.".format(repr(e)))
+    raise