diff --git a/README.md b/README.md index 6f0f7fe..4caef50 100644 --- a/README.md +++ b/README.md @@ -17,6 +17,7 @@ A [customizable](/config/template_config.ini), [multilanguage](/strings) Telegra 1. Download the project files through `git clone https://github.com/Steffo99/greed.git` (recommended) or [this link](https://github.com/Steffo99/greed/archive/master.zip). 2. Install the project requirements with `pip install -r requirements.txt` +3. _Optional: run `pip install coloredlogs` to have colored logging output._ 3. Run `python -OO core.py` to generate the configuration file. 4. Open the config folder and edit the `config.ini` file following the contained instructions. Ensure the `is_template` field is set to `no`. diff --git a/config/template_config.ini b/config/template_config.ini index 60b41f8..9cd64fc 100644 --- a/config/template_config.ini +++ b/config/template_config.ini @@ -5,7 +5,7 @@ # Config file parameters [Config] ; Config file version. DO NOT EDIT THIS! -version = 16 +version = 17 ; Set this to no when you are done editing the file is_template = yes ; Language code for string file @@ -87,3 +87,12 @@ refill_on_checkout = yes ; Optional sentry token: get the token at https://sentry.io/ or ask @Steffo for one ; Needed to automatically report bugs found by the users in the code. sentry_token = https://00000000000000000000000000000000:00000000000000000000000000000000@sentry.io/0000000 + +# Logging settings +[Logging] +; The output format for the messages printed to the console +; See https://docs.python.org/3/library/logging.html#logrecord-attributes for information about the {}-attributes +format = {asctime} | {threadName} | {name} | {message} +; Logging level: ignore all log entries with a level lower than the specified one +; Valid options are FATAL, ERROR, WARNING, INFO, and DEBUG +level = INFO diff --git a/configloader.py b/configloader.py index 87d21e6..9d8d264 100644 --- a/configloader.py +++ b/configloader.py @@ -1,9 +1,16 @@ import sys import os import configparser +import logging + + +# Logs won't show up for this file as it is imported before logging is configured +log = logging.getLogger(__name__) + # Check if the config file exists, and create one if it doesn't if not os.path.isfile("config/config.ini"): + log.debug("Creating config.ini from template_config.ini") # Open the template file and create the config file with open("config/template_config.ini", encoding="utf8") as template_file, \ open("config/config.ini", "w", encoding="utf8") as config_file: @@ -15,27 +22,34 @@ with open("config/template_config.ini", encoding="utf8") as template_file: config = configparser.ConfigParser() config.read_file(template_file) template_version = int(config["Config"]["version"]) + log.debug(f"Template is version {template_version}") # Overwrite the template config with the values in the config with open("config/config.ini", encoding="utf8") as config_file: config.read_file(config_file) + config_version = int(config["Config"]["version"]) + log.debug(f"Config is version {template_version}") # Check if the file has been edited if config["Config"]["is_template"] == "yes": - print("A config file has been created in config/config.ini.\n" - "Edit it with your configuration, set the is_template flag to false and restart this script.") + log.debug("Config is a template, aborting...") + log.fatal("A config file has been created in config/config.ini.\n" + "Edit it with your configuration, set the is_template flag to 'no' and restart this script.") sys.exit(1) # Check if the version has changed from the template -if template_version > int(config["Config"]["version"]): +if template_version > config_version: + log.debug("Config is older than Template, trying to merge...") # Reset the is_template flag config["Config"]["is_template"] = "yes" # Update the config version config["Config"]["version"] = str(template_version) # Save the file with open("config/config.ini", "w", encoding="utf8") as config_file: + log.debug("Writing merged config file...") config.write(config_file) # Notify the user and quit - print("The config file in config/config.ini has been updated.\n" - "Edit it with the new required data, set the is_template flag to true and restart this script.") + log.debug("Config is now a template, aborting...") + log.fatal("The config file in config/config.ini has been updated.\n" + "Edit it with the new required data, set the is_template flag to true and restart this script.") sys.exit(1) diff --git a/core.py b/core.py index bf9e6f5..5245eba 100644 --- a/core.py +++ b/core.py @@ -5,6 +5,12 @@ import configloader import utils import threading import importlib +import logging + +try: + import coloredlogs +except ImportError: + coloredlogs = None language = configloader.config["Config"]["language"] strings = importlib.import_module("strings." + language) @@ -12,34 +18,50 @@ strings = importlib.import_module("strings." + language) def main(): """The core code of the program. Should be run only in the main process!""" - # Rename the main thread for presentation purposes threading.current_thread().name = "Core" + # Setup logging + log = logging.getLogger("core") + logging.root.setLevel(configloader.config["Logging"]["level"]) + stream_handler = logging.StreamHandler() + if coloredlogs is not None: + stream_handler.formatter = coloredlogs.ColoredFormatter(configloader.config["Logging"]["format"], style="{") + else: + stream_handler.formatter = logging.Formatter(configloader.config["Logging"]["format"], style="{") + logging.root.handlers.clear() + logging.root.addHandler(stream_handler) + log.debug("Logging setup successfully!") + + # Ignore most python-telegram-bot logs, as they are useless most of the time + logging.getLogger("telegram").setLevel("ERROR") + # Create a bot instance bot = utils.DuckBot(configloader.config["Telegram"]["token"]) # Test the specified token + log.debug("Testing bot token...") try: bot.get_me() except telegram.error.Unauthorized: - print("The token you have entered in the config file is invalid.\n" - "Fix it, then restart this script.") + logging.fatal("The token you have entered in the config file is invalid. Fix it, then restart greed.") 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 next_update = None # Notify on the console that the bot is starting - print("greed-bot is now starting!") + log.info("greed is starting!") # Main loop of the program while True: # Get a new batch of 100 updates and mark the last 100 parsed as read + log.debug("Getting updates from Telegram") updates = bot.get_updates(offset=next_update, timeout=int(configloader.config["Telegram"]["long_polling_timeout"])) # Parse all the updates @@ -48,20 +70,24 @@ def main(): if update.message is not None: # Ensure the message has been sent in a private chat if update.message.chat.type != "private": + log.debug(f"Received a message from a non-private chat: {update.message.chat.id}") # Notify the chat bot.send_message(update.message.chat.id, strings.error_nonprivate_chat) # Skip the update continue # If the message is a start command... if isinstance(update.message.text, str) and update.message.text.startswith("/start"): + log.info(f"Received /start from: {update.message.chat.id}") # Check if a worker already exists for that chat old_worker = chat_workers.get(update.message.chat.id) # If it exists, gracefully stop the worker if old_worker: + 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() # Store the worker in the dictionary chat_workers[update.message.chat.id] = new_worker @@ -71,6 +97,7 @@ def main(): receiving_worker = chat_workers.get(update.message.chat.id) # Ensure a worker exists for the chat and is alive if receiving_worker is None or not receiving_worker.is_alive(): + log.debug(f"Received a message in a chat without worker: {update.message.chat.id}") # Suggest that the user restarts the chat with /start bot.send_message(update.message.chat.id, strings.error_no_worker_for_chat, reply_markup=telegram.ReplyKeyboardRemove()) @@ -78,9 +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 {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 {receiving_worker}") # Forward the update to the worker receiving_worker.queue.put(update) # If the update is a inline keyboard press... @@ -89,17 +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.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 {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 {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 @@ -107,17 +139,19 @@ def main(): # Forward the update to the corresponding worker receiving_worker = chat_workers.get(update.pre_checkout_query.from_user.id) # Check if it's the active invoice for this chat - if receiving_worker is None or\ + if receiving_worker is None or \ update.pre_checkout_query.invoice_payload != receiving_worker.invoice_payload: # Notify the user that the invoice has expired + log.debug(f"Received a pre-checkout query for an expired invoice in: {update.message.chat.id}") try: bot.answer_pre_checkout_query(update.pre_checkout_query.id, ok=False, error_message=strings.error_invoice_expired) except telegram.error.BadRequest: - print(f"ERROR: pre_checkout_query expired before an answer could be sent") + 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 {receiving_worker}") # Forward the update to the worker receiving_worker.queue.put(update) # If there were any updates... diff --git a/utils.py b/utils.py index 296cbeb..d36bc6d 100644 --- a/utils.py +++ b/utils.py @@ -6,6 +6,12 @@ import typing import os import sys import importlib +import logging +import traceback + + +log = logging.getLogger(__name__) + language = config["Config"]["language"] try: @@ -132,38 +138,38 @@ def catch_telegram_errors(func): return func(*args, **kwargs) # Bot was blocked by the user except telegram.error.Unauthorized: - print(f"Unauthorized to call {func.__name__}(), skipping.") + log.debug(f"Unauthorized to call {func.__name__}(), skipping.") break # Telegram API didn't answer in time except telegram.error.TimedOut: - print(f"Timed out while calling {func.__name__}()," - f" retrying in {config['Telegram']['timed_out_pause']} secs...") + log.warning(f"Timed out while calling {func.__name__}()," + f" retrying in {config['Telegram']['timed_out_pause']} secs...") time.sleep(int(config["Telegram"]["timed_out_pause"])) # Telegram is not reachable except telegram.error.NetworkError as error: - print(f"Network error while calling {func.__name__}()," - f" retrying in {config['Telegram']['error_pause']} secs...") - # Display the full NetworkError - print(f"Full error: {error.message}") + log.error(f"Network error while calling {func.__name__}()," + f" retrying in {config['Telegram']['error_pause']} secs...\n" + f"Full error: {error.message}") time.sleep(int(config["Telegram"]["error_pause"])) # Unknown error except telegram.error.TelegramError as error: if error.message.lower() in ["bad gateway", "invalid server response"]: - print(f"Bad Gateway while calling {func.__name__}()," - f" retrying in {config['Telegram']['error_pause']} secs...") + log.warning(f"Bad Gateway while calling {func.__name__}()," + f" retrying in {config['Telegram']['error_pause']} secs...") time.sleep(int(config["Telegram"]["error_pause"])) elif error.message.lower() == "timed out": - print(f"Timed out while calling {func.__name__}()," - f" retrying in {config['Telegram']['timed_out_pause']} secs...") + log.warning(f"Timed out while calling {func.__name__}()," + f" retrying in {config['Telegram']['timed_out_pause']} secs...") time.sleep(int(config["Telegram"]["timed_out_pause"])) else: - print(f"Telegram error while calling {func.__name__}()," - f" retrying in {config['Telegram']['error_pause']} secs...") - # Display the full TelegramError - print(f"Full error: {error.message}") + log.error(f"Telegram error while calling {func.__name__}()," + f" retrying in {config['Telegram']['error_pause']} secs...\n" + f"Full error: {error.message}") # Send the error to the Sentry server if sentry_client is not None: sentry_client.captureException(exc_info=sys.exc_info()) + else: + traceback.print_exception(*sys.exc_info()) time.sleep(int(config["Telegram"]["error_pause"])) return result_func diff --git a/worker.py b/worker.py index e9126c4..5f031e4 100644 --- a/worker.py +++ b/worker.py @@ -14,6 +14,9 @@ import traceback from html import escape import requests import importlib +import logging + +log = logging.getLogger(__name__) language = configloader.config["Config"]["language"] strings = importlib.import_module("strings." + language) @@ -21,7 +24,6 @@ strings = importlib.import_module("strings." + language) class StopSignal: """A data class that should be sent to the worker when the conversation has to be stopped abnormally.""" - def __init__(self, reason: str = ""): self.reason = reason @@ -31,7 +33,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 +43,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 +59,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 +100,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 +135,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 +162,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() @@ -176,6 +189,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() @@ -206,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() @@ -226,6 +241,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() @@ -240,6 +256,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() @@ -264,6 +281,7 @@ class ChatWorker(threading.Thread): def __wait_for_inlinekeyboard_callback(self, cancellable: bool = False) \ -> 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() @@ -286,6 +304,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 @@ -315,6 +334,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 @@ -355,6 +375,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' @@ -575,6 +596,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) \ @@ -591,6 +613,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 @@ -623,6 +646,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 presets = list(map(lambda s: s.strip(" "), configloader.config["Credit Card"]["payment_presets"].split('|'))) keyboard = [[telegram.KeyboardButton(str(utils.Price(preset)))] for preset in presets] @@ -730,11 +754,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 @@ -791,6 +817,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 @@ -827,6 +854,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")]]) @@ -915,6 +943,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 @@ -942,6 +971,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")]]) @@ -1033,6 +1063,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 @@ -1075,6 +1106,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)], @@ -1102,6 +1134,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 @@ -1156,6 +1189,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 @@ -1201,6 +1235,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 @@ -1265,6 +1300,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