Enable logging in core

README.md

@@ -17,6 +17,7 @@ A customizable Telegram shop bot, developed as a project for the final exam.
 
 1. Download the project files through `git clone https://github.com/Steffo99/greed.git` 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`.

config/template_config.ini

@@ -5,7 +5,7 @@
 # Config file parameters
 [Config]
 ; Config file version. DO NOT EDIT THIS!
-version = 14
+version = 15
 ; Set this to no when you are done editing the file
 is_template = yes
 ; Language code for string file
@@ -75,3 +75,12 @@ full_order_info = no
 ; 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

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,20 +18,35 @@ 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"
+        logging.fatal("The token you have entered in the config file is invalid. Fix it, then restart greed.")
-              "Fix it, then restart this script.")
         sys.exit(1)
+    log.debug("Bot token is valid!")
 
     # Create a dictionary linking the chat ids to the ChatWorker objects
     # {"1234": <ChatWorker>}
@@ -35,11 +56,12 @@ def main():
     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 == "/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)
                     # 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 {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}")
                     # 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.message.chat.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}")
                     # 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}")
                     # 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
@@ -110,14 +142,16 @@ def main():
                 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 {worker}")
                 # Forward the update to the worker
                 receiving_worker.queue.put(update)
         # If there were any updates...