From 68eafef6563a4e827f8dc9c89502b80b6d0499cf Mon Sep 17 00:00:00 2001 From: Stefano Pigozzi Date: Thu, 23 Apr 2020 17:10:28 +0200 Subject: [PATCH] Improve logging system (and rename ChatWorker class to Worker) --- core.py | 18 +++++++++--------- worker.py | 50 ++++++++++++++++++++++++++++++++++++++++++++++---- 2 files changed, 55 insertions(+), 13 deletions(-) diff --git a/core.py b/core.py index 543c4f8..6ab73ab 100644 --- a/core.py +++ b/core.py @@ -48,8 +48,8 @@ def main(): sys.exit(1) log.debug("Bot token is valid!") - # Create a dictionary linking the chat ids to the ChatWorker objects - # {"1234": } + # Create a dictionary linking the chat ids to the Worker objects + # {"1234": } chat_workers = {} # Current update offset; if None it will get the last 100 unparsed messages @@ -85,7 +85,7 @@ def main(): log.debug(f"Received request to stop {old_worker.name}") old_worker.stop("request") # Initialize a new worker for the chat - new_worker = worker.ChatWorker(bot, update.message.chat) + new_worker = worker.Worker(bot, update.message.chat) # Start the worker log.debug(f"Starting {new_worker.name}") new_worker.start() @@ -105,11 +105,11 @@ def main(): continue # If the message contains the "Cancel" string defined in the strings file... if update.message.text == strings.menu_cancel: - log.debug(f"Forwarding CancelSignal to {worker}") + log.debug(f"Forwarding CancelSignal to {receiving_worker}") # Send a CancelSignal to the worker instead of the update receiving_worker.queue.put(worker.CancelSignal()) else: - log.debug(f"Forwarding message to {worker}") + log.debug(f"Forwarding message to {receiving_worker}") # Forward the update to the worker receiving_worker.queue.put(update) # If the update is a inline keyboard press... @@ -118,20 +118,20 @@ def main(): receiving_worker = chat_workers.get(update.callback_query.from_user.id) # Ensure a worker exists for the chat if receiving_worker is None: - log.debug(f"Received a callback query in a chat without worker: {update.message.chat.id}") + log.debug(f"Received a callback query in a chat without worker: {update.callback_query.from_user.id}") # Suggest that the user restarts the chat with /start bot.send_message(update.callback_query.from_user.id, strings.error_no_worker_for_chat) # Skip the update continue # Check if the pressed inline key is a cancel button if update.callback_query.data == "cmd_cancel": - log.debug(f"Forwarding CancelSignal to {worker}") + log.debug(f"Forwarding CancelSignal to {receiving_worker}") # Forward a CancelSignal to the worker receiving_worker.queue.put(worker.CancelSignal()) # Notify the Telegram client that the inline keyboard press has been received bot.answer_callback_query(update.callback_query.id) else: - log.debug(f"Forwarding callback query to {worker}") + log.debug(f"Forwarding callback query to {receiving_worker}") # Forward the update to the worker receiving_worker.queue.put(update) # If the update is a precheckoutquery, ensure it hasn't expired before forwarding it @@ -151,7 +151,7 @@ def main(): log.error("pre-checkout query expired before an answer could be sent!") # Go to the next update continue - log.debug(f"Forwarding pre-checkout query to {worker}") + log.debug(f"Forwarding pre-checkout query to {receiving_worker}") # Forward the update to the worker receiving_worker.queue.put(update) # If there were any updates... diff --git a/worker.py b/worker.py index 4de75af..2336f68 100644 --- a/worker.py +++ b/worker.py @@ -14,6 +14,14 @@ import traceback from html import escape import requests import importlib +import logging + +try: + import coloredlogs +except ImportError: + coloredlogs = None + +log = logging.getLogger(__name__) language = configloader.config["Config"]["language"] strings = importlib.import_module("strings." + language) @@ -31,7 +39,7 @@ class CancelSignal: pass -class ChatWorker(threading.Thread): +class Worker(threading.Thread): """A worker for a single conversation. A new one is created every time the /start command is sent.""" def __init__(self, bot: utils.DuckBot, chat: telegram.Chat, *args, **kwargs): @@ -41,11 +49,12 @@ class ChatWorker(threading.Thread): self.bot: utils.DuckBot = bot self.chat: telegram.Chat = chat # Open a new database session + log.debug(f"Opening new database session for {self.name}") self.session = db.Session() # Get the user db data from the users and admin tables self.user: Optional[db.User] = None self.admin: Optional[db.Admin] = None - # The sending pipe is stored in the ChatWorker class, allowing the forwarding of messages to the chat process + # The sending pipe is stored in the Worker class, allowing the forwarding of messages to the chat process self.queue = queuem.Queue() # The current active invoice payload; reject all invoices with a different payload self.invoice_payload = None @@ -56,13 +65,19 @@ class ChatWorker(threading.Thread): self.sentry_client = raven.Client(configloader.config["Error Reporting"]["sentry_token"], release=raven.fetch_git_sha(os.path.dirname(__file__)), environment="Dev" if __debug__ else "Prod") + log.debug("Sentry: enabled") else: self.sentry_client = None + log.debug("Sentry: disabled") + + def __repr__(self): + return f"<{self.__class__.__qualname__} {self.chat.id}>" # noinspection PyBroadException def run(self): """The conversation code.""" # Welcome the user to the bot + log.debug("Starting conversation") self.bot.send_message(self.chat.id, strings.conversation_after_start) # Get the user db data from the users and admin tables self.user = self.session.query(db.User).filter(db.User.user_id == self.chat.id).one_or_none() @@ -91,6 +106,9 @@ class ChatWorker(threading.Thread): self.session.add(self.admin) # Commit the transaction self.session.commit() + log.info(f"Created new user: {self.user}") + if will_be_owner: + log.warning(f"User was auto-promoted to Admin as no other admins existed: {self.user}") # Capture exceptions that occour during the conversation try: # If the user is not an admin, send him to the user menu @@ -123,8 +141,8 @@ class ChatWorker(threading.Thread): self.join() def update_user(self) -> db.User: - """Update the user data. - Note that this method will cause crashes if used in different threads with sqlite databases.""" + """Update the user data.""" + log.debug("Fetching updated user data from the database") self.user = self.session.query(db.User).filter(db.User.user_id == self.chat.id).one_or_none() return self.user @@ -150,6 +168,7 @@ class ChatWorker(threading.Thread): items: List[str], cancellable: bool = False) -> Union[str, CancelSignal]: """Continue getting updates until until one of the strings contained in the list is received as a message.""" + log.debug("Waiting for a specific message...") while True: # Get the next update update = self.__receive_next_update() @@ -175,6 +194,7 @@ class ChatWorker(threading.Thread): def __wait_for_regex(self, regex: str, cancellable: bool = False) -> Union[str, CancelSignal]: """Continue getting updates until the regex finds a match in a message, then return the first capture group.""" + log.debug("Waiting for a regex...") while True: # Get the next update update = self.__receive_next_update() @@ -200,6 +220,7 @@ class ChatWorker(threading.Thread): cancellable: bool = False) -> Union[telegram.PreCheckoutQuery, CancelSignal]: """Continue getting updates until a precheckoutquery is received. The payload is checked by the core before forwarding the message.""" + log.debug("Waiting for a PreCheckoutQuery...") while True: # Get the next update update = self.__receive_next_update() @@ -215,6 +236,7 @@ class ChatWorker(threading.Thread): def __wait_for_successfulpayment(self) -> telegram.SuccessfulPayment: """Continue getting updates until a successfulpayment is received.""" + log.debug("Waiting for a SuccessfulPayment...") while True: # Get the next update update = self.__receive_next_update() @@ -229,6 +251,7 @@ class ChatWorker(threading.Thread): def __wait_for_photo(self, cancellable: bool = False) -> Union[List[telegram.PhotoSize], CancelSignal]: """Continue getting updates until a photo is received, then return it.""" + log.debug("Waiting for a photo...") while True: # Get the next update update = self.__receive_next_update() @@ -248,6 +271,7 @@ class ChatWorker(threading.Thread): def __wait_for_inlinekeyboard_callback(self, cancellable: bool = True) \ -> Union[telegram.CallbackQuery, CancelSignal]: """Continue getting updates until an inline keyboard callback is received, then return it.""" + log.debug("Waiting for a CallbackQuery...") while True: # Get the next update update = self.__receive_next_update() @@ -265,6 +289,7 @@ class ChatWorker(threading.Thread): def __user_select(self) -> Union[db.User, CancelSignal]: """Select an user from the ones in the database.""" + log.debug("Waiting for a user selection...") # Find all the users in the database users = self.session.query(db.User).order_by(db.User.user_id).all() # Create a list containing all the keyboard button strings @@ -294,6 +319,7 @@ class ChatWorker(threading.Thread): def __user_menu(self): """Function called from the run method when the user is not an administrator. Normal bot actions should be placed here.""" + log.debug("Displaying __user_menu") # Loop used to returning to the menu after executing a command while True: # Create a keyboard with the user main menu @@ -334,6 +360,7 @@ class ChatWorker(threading.Thread): def __order_menu(self): """User menu to order products from the shop.""" + log.debug("Displaying __order_menu") # Get the products list from the db products = self.session.query(db.Product).filter_by(deleted=False).all() # Create a dict to be used as 'cart' @@ -530,6 +557,7 @@ class ChatWorker(threading.Thread): def __order_status(self): """Display the status of the sent orders.""" + log.debug("Displaying __order_status") # Find the latest orders orders = self.session.query(db.Order) \ .filter(db.Order.user == self.user) \ @@ -546,6 +574,7 @@ class ChatWorker(threading.Thread): def __add_credit_menu(self): """Add more credit to the account.""" + log.debug("Displaying __add_credit_menu") # Create a payment methods keyboard keyboard = list() # Add the supported payment methods to the keyboard @@ -577,6 +606,7 @@ class ChatWorker(threading.Thread): def __add_credit_cc(self): """Add money to the wallet through a credit card payment.""" + log.debug("Displaying __add_credit_cc") # Create a keyboard to be sent later keyboard = [[telegram.KeyboardButton(str(utils.Price("10.00")))], [telegram.KeyboardButton(str(utils.Price("25.00")))], @@ -672,11 +702,13 @@ class ChatWorker(threading.Thread): def __bot_info(self): """Send information about the bot.""" + log.debug("Displaying __bot_info") self.bot.send_message(self.chat.id, strings.bot_info) def __admin_menu(self): """Function called from the run method when the user is an administrator. Administrative bot actions should be placed here.""" + log.debug("Displaying __admin_menu") # Loop used to return to the menu after executing a command while True: # Create a keyboard with the admin main menu based on the admin permissions specified in the db @@ -733,6 +765,7 @@ class ChatWorker(threading.Thread): def __products_menu(self): """Display the admin menu to select a product to edit.""" + log.debug("Displaying __products_menu") # Get the products list from the db products = self.session.query(db.Product).filter_by(deleted=False).all() # Create a list of product names @@ -769,6 +802,7 @@ class ChatWorker(threading.Thread): def __edit_product_menu(self, product: Optional[db.Product] = None): """Add a product to the database or edit an existing one.""" + log.debug("Displaying __edit_product_menu") # Create an inline keyboard with a single skip button cancel = telegram.InlineKeyboardMarkup([[telegram.InlineKeyboardButton(strings.menu_skip, callback_data="cmd_cancel")]]) @@ -857,6 +891,7 @@ class ChatWorker(threading.Thread): self.bot.send_message(self.chat.id, strings.success_product_edited) def __delete_product_menu(self): + log.debug("Displaying __delete_product_menu") # Get the products list from the db products = self.session.query(db.Product).filter_by(deleted=False).all() # Create a list of product names @@ -884,6 +919,7 @@ class ChatWorker(threading.Thread): def __orders_menu(self): """Display a live flow of orders.""" + log.debug("Displaying __orders_menu") # Create a cancel and a stop keyboard stop_keyboard = telegram.InlineKeyboardMarkup([[telegram.InlineKeyboardButton(strings.menu_stop, callback_data="cmd_cancel")]]) @@ -975,6 +1011,7 @@ class ChatWorker(threading.Thread): def __create_transaction(self): """Edit manually the credit of an user.""" + log.debug("Displaying __create_transaction") # Make the admin select an user user = self.__user_select() # Allow the cancellation of the operation @@ -1017,6 +1054,7 @@ class ChatWorker(threading.Thread): def __help_menu(self): """Help menu. Allows the user to ask for assistance, get a guide or see some info about the bot.""" + log.debug("Displaying __help_menu") # Create a keyboard with the user help menu keyboard = [[telegram.KeyboardButton(strings.menu_guide)], [telegram.KeyboardButton(strings.menu_contact_shopkeeper)], @@ -1044,6 +1082,7 @@ class ChatWorker(threading.Thread): def __transaction_pages(self): """Display the latest transactions, in pages.""" + log.debug("Displaying __transaction_pages") # Page number page = 0 # Create and send a placeholder message to be populated @@ -1098,6 +1137,7 @@ class ChatWorker(threading.Thread): def __transactions_file(self): """Generate a .csv file containing the list of all transactions.""" + log.debug("Generating __transaction_file") # Retrieve all the transactions transactions = self.session.query(db.Transaction).order_by(db.Transaction.transaction_id.asc()).all() # Create the file if it doesn't exists @@ -1143,6 +1183,7 @@ class ChatWorker(threading.Thread): def __add_admin(self): """Add an administrator to the bot.""" + log.debug("Displaying __add_admin") # Let the admin select an administrator to promote user = self.__user_select() # Allow the cancellation of the operation @@ -1207,6 +1248,7 @@ class ChatWorker(threading.Thread): def __graceful_stop(self, stop_trigger: StopSignal): """Handle the graceful stop of the thread.""" + log.debug("Gracefully stopping the conversation") # If the session has expired... if stop_trigger.reason == "timeout": # Notify the user that the session has expired and remove the keyboard