Logging added. LOG_LEVEL env variable introduced.

bot.py

@@ -9,10 +9,13 @@ from telegram import CommandProcessor
 load_dotenv()
 
 token = os.getenv('TELEGRAM_TOKEN')
-db_path = os.getenv('DATABASE_PATH')
+db_path = os.getenv('DATABASE_PATH', './bot.db')
+log_level = os.getenv('LOG_LEVEL', 'INFO')
 
-db = Database(db_path)
-bot = CommandProcessor(token, db)
+print('Starting the bot with logging level', log_level.upper())
+logging.basicConfig(level=log_level.upper(), format='%(asctime)s: <%(name)s> [%(levelname)s] %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
+
+db = Database(db_path, logging.getLogger('Database'))
+bot = CommandProcessor(token, db, logging.getLogger('CommandProcessor'))
 
-logging.info("Starting Telegram bot")
 bot.run()

database.py

@@ -1,5 +1,7 @@
 import sqlite3
 
+from logging import Logger
+
 from exceptions import DisplayableException
 from rss import FeedItem
 
@@ -7,8 +9,10 @@ from rss import FeedItem
 class Database:
     """Implement interaction with the database."""
 
-    def __init__(self, path: str) -> None:
+    def __init__(self, path: str, log: Logger) -> None:
         """Create a database file if not exists."""
+        self.log: Logger = log
+        self.log.debug('Database.__init__(path=\'%s\')', path)
         # TODO: think about removing check_same_thread=False
         self.conn = sqlite3.connect(path, check_same_thread=False)
         self.conn.row_factory = sqlite3.Row
@@ -17,12 +21,14 @@ class Database:
 
     def add_user(self, telegram_id: int) -> int:
         """Add a user's telegram id to the database and return its database id."""
+        self.log.debug('add_user(telegram_id=\'%s\')', telegram_id)
         self.cur.execute('INSERT INTO users (telegram_id) VALUES (?)', [telegram_id])
         self.conn.commit()
         return self.cur.lastrowid
 
     def find_user(self, telegram_id: int) -> int | None:
         """Get a user's telegram id and return its database id."""
+        self.log.debug('find_user(telegram_id=\'%s\')', telegram_id)
         self.cur.execute('SELECT id FROM users WHERE telegram_id = ?', [telegram_id])
         row = self.cur.fetchone()
         if row is None:
@@ -31,12 +37,14 @@ class Database:
 
     def add_feed(self, url: str) -> int:
         """Add a feed to the database and return its id."""
+        self.log.debug('add_feed(url=\'%s\')', url)
         self.cur.execute('INSERT INTO feeds (url) VALUES (?)', [url])
         self.conn.commit()
         return self.cur.lastrowid
 
     def find_feed_by_url(self, url: str) -> int | None:
         """Find feed ID by url."""
+        self.log.debug('find_feed_by_url(url=\'%s\')', url)
         self.cur.execute('SELECT id FROM feeds WHERE url = ?', [url])
         row = self.cur.fetchone()
         if row is None:
@@ -45,6 +53,7 @@ class Database:
 
     def subscribe_user_by_url(self, user_id: int, url: str) -> None:
         """Subscribe user to the feed creating it if does not exist yet."""
+        self.log.debug('subscribe_user_by_url(user_id=\'%s\', url=\'%s\')', user_id, url)
         feed_id = self.find_feed_by_url(url)
         if feed_id is None:
             feed_id = self.add_feed(url)
@@ -56,11 +65,13 @@ class Database:
 
     def subscribe_user(self, user_id: int, feed_id: int) -> None:
         """Subscribe a user to the feed."""
+        self.log.debug('subscribe_user(user_id=\'%s\', feed_id=\'%s\')', user_id, feed_id)
         self.cur.execute('INSERT INTO subscriptions (user_id, feed_id) VALUES (?, ?)', [user_id, feed_id])
         self.conn.commit()
 
     def unsubscribe_user_by_url(self, user_id: int, url: str) -> None:
         """Subscribe a user to the feed by url."""
+        self.log.debug('unsubscribe_user_by_url(user_id=\'%s\', url=\'%s\')', user_id, url)
         feed_id = self.find_feed_by_url(url)
         if feed_id is None:
             raise DisplayableException('Feed does not exist')
@@ -76,11 +87,13 @@ class Database:
 
     def unsubscribe_user(self, user_id: int, feed_id: int) -> None:
         """Unsubscribe a user from the feed."""
+        self.log.debug('unsubscribe_user(user_id=\'%s\', feed_id=\'%s\')', user_id, feed_id)
         self.cur.execute('DELETE FROM subscriptions WHERE feed_id = ? AND user_id = ?', [feed_id, user_id])
         self.conn.commit()
 
     def is_user_subscribed(self, user_id: int, feed_id: int) -> bool:
         """Check if user subscribed to specific feed."""
+        self.log.debug('is_user_subscribed(user_id=\'%s\', feed_id=\'%s\')', user_id, feed_id)
         self.cur.execute('SELECT 1 FROM subscriptions WHERE user_id = ? AND feed_id = ?', [user_id, feed_id])
         row = self.cur.fetchone()
         if row is None:
@@ -89,17 +102,20 @@ class Database:
 
     def delete_feed(self, feed_id: int) -> None:
         """Delete a feed."""
+        self.log.debug('delete_feed(feed_id=\'%s\')', feed_id)
         self.cur.execute('DELETE FROM feeds WHERE id = ?', [feed_id])
         self.conn.commit()
 
     def get_feed_subscribers_count(self, feed_id: int) -> int:
         """Count feed subscribers."""
+        self.log.debug('get_feed_subscribers_count(feed_id=\'%s\')', feed_id)
         self.cur.execute('SELECT COUNT(user_id) AS amount_subscribers FROM subscriptions WHERE feed_id = ?', [feed_id])
         row = self.cur.fetchone()
         return row['amount_subscribers']
 
     def find_feed_subscribers(self, feed_id: int) -> list[int]:
         """Return feed subscribers"""
+        self.log.debug('find_feed_subscribers(feed_id=\'%s\')', feed_id)
         self.cur.execute('SELECT telegram_id FROM users WHERE id IN (SELECT user_id FROM subscriptions WHERE feed_id = ?)',
                          [feed_id])
         subscribers = self.cur.fetchall()
@@ -107,29 +123,34 @@ class Database:
 
     def find_feeds(self) -> list[sqlite3.Row]:
         """Get a list of feeds."""
+        self.log.debug('find_feeds()')
         self.cur.execute('SELECT * FROM feeds')
         return self.cur.fetchall()
 
     def find_user_feeds(self, user_id: int) -> list[sqlite3.Row]:
         """Return a list of feeds the user is subscribed to."""
+        self.log.debug('find_user_feeds(user_id=\'%s\')', user_id)
         self.cur.execute('SELECT * FROM feeds WHERE id IN (SELECT feed_id FROM subscriptions WHERE user_id = ?)',
                          [user_id])
         return self.cur.fetchall()
 
     def find_feed_items(self, feed_id: int) -> list[sqlite3.Row]:
         """Get last feed items."""
+        self.log.debug('find_feed_items(feed_id=\'%s\')', feed_id)
         self.cur.execute('SELECT * FROM feeds_last_items WHERE feed_id = ?', [feed_id])
         return self.cur.fetchall()
 
     def find_feed_items_urls(self, feed_id: int) -> list[str]:
         """Return urls last feed items"""
+        self.log.debug('find_feed_items_urls(feed_id=\'%s\')', feed_id)
         items = self.find_feed_items(feed_id)
         if not items:
-            return items
+            return []
         return list(map(lambda x: x['url'], items))
 
     def update_feed_items(self, feed_id: int, new_items: list[FeedItem]) -> None:
         """Replace last feed items with a list items that receive."""
+        self.log.debug('update_feed_items(feed_id=\'%s\', new_items=list(%d))', feed_id, len(new_items))
         for i, _ in enumerate(new_items):
             new_items[i] = [feed_id] + list(new_items[i].__dict__.values())[:-1]
 
@@ -138,8 +159,9 @@ class Database:
             'INSERT INTO feeds_last_items (feed_id, url, title, description) VALUES (?, ?, ?, ?)', new_items)
         self.conn.commit()
 
-    def __init_schema(self):
-        # TODO: Move to migrations
+    def __init_schema(self) -> None:
+        self.log.debug('__init_schema()')
+        # TODO: Change to migrations
         self.cur.execute(
             'CREATE TABLE IF NOT EXISTS users (id INTEGER, telegram_id INTEGER NOT NULL UNIQUE, PRIMARY KEY(id))'
         )

rss.py

@@ -1,3 +1,5 @@
+from logging import Logger
+
 from feedparser import FeedParserDict, parse
 
 
@@ -22,5 +24,11 @@ class Feed:
 
 
 class RssReader:
+
+    def __init__(self, logger: Logger):
+        self.log: Logger = logger
+        self.log.debug('RssReader.__init__(logger=%s)', logger)
+
     def get_feed(self, url: str) -> Feed:
+        self.log.debug('get_feed(url=\'%s\')', url)
         return Feed(url, parse(url))

telegram.py

@@ -1,5 +1,6 @@
 import time
 
+from logging import Logger
 from telebot import TeleBot
 from telebot.handler_backends import BaseMiddleware
 from telebot.types import Message
@@ -13,25 +14,32 @@ from rss import FeedItem
 class CommandProcessor:
     """Processes user input and dispatches the data to other services."""
 
-    def __init__(self, token: str, database: Database):
+    def __init__(self, token: str, database: Database, logger: Logger):
+        self.log = logger
+        self.log.debug(
+            'CommandProcessor.__init__(token=\'%s\', database=%s, logger=%s)', token[:8] + '...', database, logger
+        )
         if token is None or len(token) == 0:
             raise ValueError("Token should not be empty")
         self.bot: TeleBot = TeleBot(token, use_class_middlewares=True)
-        self.bot.setup_middleware(UserAuthMiddleware(database))
-        self.bot.setup_middleware(ExceptionHandlerMiddleware(self.bot))
+        self.bot.setup_middleware(UserAuthMiddleware(database, logger))
+        self.bot.setup_middleware(ExceptionHandlerMiddleware(self.bot, logger))
         self.database: Database = database
 
     def run(self):
         """Run a bot and poll for new messages indefinitely."""
+        self.log.debug('Registering handlers')
         self.bot.register_message_handler(commands=['add'], callback=self.__add_feed)
         self.bot.register_message_handler(commands=['list'], callback=self.__list_feeds)
         self.bot.register_message_handler(commands=['del'], callback=self.__delete_feed)
         self.bot.register_message_handler(commands=['help', 'start'], callback=self.__command_help)
         self.bot.register_message_handler(callback=self.__command_help)
 
+        self.log.info('Starting to poll the servers')
         self.bot.infinity_polling()
 
     def __command_help(self, message: Message, data: dict):
+        self.log.debug('__command_help(message=\'%s\', data=\'%s\')', message, data)
         self.bot.reply_to(
             message,
             'Supported commands:\n'
@@ -42,19 +50,23 @@ class CommandProcessor:
         )
 
     def __add_feed(self, message: Message, data: dict):
+        self.log.debug('__add_feed(message=\'%s\', data=\'%s\')', message, data)
         args = message.text.split()
         if len(args) < 2:
             raise DisplayableException('Feed URL should be specified')
 
         url = str(args[1])
+        self.log.info('User %s requested to subscribe to %s', data['user_id'], url)
         if not self.__is_url_valid(url):
             raise DisplayableException('Invalid feed URL')
 
         self.database.subscribe_user_by_url(data['user_id'], url)
+        self.log.info('Subscription added')
 
         self.bot.reply_to(message, 'Successfully subscribed to feed.')
 
     def __list_feeds(self, message: Message, data: dict):
+        self.log.debug('__list_feeds(message=\'%s\', data=\'%s\')', message, data)
         feeds = self.database.find_user_feeds(data['user_id'])
 
         feed_list = ''
@@ -64,15 +76,18 @@ class CommandProcessor:
         self.bot.reply_to(message, 'Your feeds:\n' + feed_list)
 
     def __delete_feed(self, message: Message, data: dict):
+        self.log.debug('__delete_feed(message=\'%s\', data=\'%s\')', message, data)
         args = message.text.split()
         if len(args) < 2:
             raise DisplayableException('Feed URL should be specified')
 
         url = str(args[1])
+        self.log.info('User %s requested to unsubscribe from %s', data['user_id'], url)
         if not self.__is_url_valid(url):
             raise DisplayableException('Invalid feed URL')
 
         self.database.unsubscribe_user_by_url(data['user_id'], url)
+        self.log.info('Subscription removed')
 
         self.bot.reply_to(message, 'Unsubscribed.')
 
@@ -94,15 +109,24 @@ class Notifier:
 
     sent_counter: int = 0
 
-    def __init__(self, token: str):
+    def __init__(self, token: str, logger: Logger):
+        self.log = logger
+        self.log.debug('Notifier.__init__(token=\'%s\', logger=%s)', token[:8] + '...', logger)
         self.bot: TeleBot = TeleBot(token)
 
     def send_updates(self, chat_ids: list[int], updates: list[FeedItem], feed_title: str):
         """Send notification about new items to the user"""
+        self.log.debug(
+            'send_updates(chat_ids=list(%d), updates=list(%d), feed_title=\'%s\')',
+            len(chat_ids), len(updates), feed_title
+        )
         if not updates:
+            self.log.debug('No updates to send')
             return
 
+        self.log.debug('%d updates to send to %d chats', len(updates), len(chat_ids))
         for chat_id in chat_ids:
+            self.log.debug('Processing chat_id=%s', chat_id)
             self.__count_request_and_wait()
             self.bot.send_message(
                 chat_id=chat_id,
@@ -114,6 +138,7 @@ class Notifier:
                 self.__send_update(chat_id, update)
 
     def __send_update(self, chat_id: int, update: FeedItem):
+        self.log.debug('__send_update(chat_id=\'%s\', update=\'%s\')', chat_id, update)
         self.bot.send_message(
             chat_id=chat_id,
             text=self.__format_message(update),
@@ -121,9 +146,11 @@ class Notifier:
         )
 
     def __count_request_and_wait(self):
+        self.log.debug('__count_request_and_wait()')
         if self.sent_counter >= self.BATCH_LIMIT:
-            # TODO: probably implement better later
+            self.log.debug('Requests limit exceeded, sleeping for a second')
             time.sleep(1)
+            self.log.debug('Resetting counter')
             self.sent_counter = 0
         self.sent_counter += 1
 
@@ -139,22 +166,28 @@ class Notifier:
 class UserAuthMiddleware(BaseMiddleware):
     """Transparently authenticates and registers the user if needed."""
 
-    def __init__(self, database: Database):
+    def __init__(self, database: Database, logger: Logger):
+        self.log: Logger = logger
+        self.log.debug('UserAuthMiddleware.__init__(database=%s, logger=%s)', database, logger)
         super().__init__()
         self.update_types = ['message']
         self.database: Database = database
 
     def pre_process(self, message: Message, data: dict):
         """Pre-process update, find user and add it's ID to the handler data dictionary."""
+        self.log.debug('UserAuthMiddleware.pre_process()')
         data['user_id'] = self.__find_or_register_user(message)
 
     def post_process(self, message: Message, data: dict, exception):
         """Post-process update."""
 
     def __find_or_register_user(self, message: Message) -> int:
+        self.log.debug('__find_or_register_user()')
         telegram_id = message.from_user.id
+        self.log.debug('Telegram chat_id=%s', telegram_id)
 
         user_id = self.database.find_user(telegram_id)
+        self.log.debug('Database user ID is \'%s\'', user_id)
         if user_id is None:
             return self.database.add_user(telegram_id)
         return user_id
@@ -163,7 +196,9 @@ class UserAuthMiddleware(BaseMiddleware):
 class ExceptionHandlerMiddleware(BaseMiddleware):
     """Sends messages to the user on exception."""
 
-    def __init__(self, bot: TeleBot):
+    def __init__(self, bot: TeleBot, logger: Logger):
+        self.log: Logger = logger
+        self.log.debug('ExceptionHandlerMiddleware.__init__(bot=%s, logger=%s)', bot, logger)
         super().__init__()
         self.update_types = ['message']
         self.bot: TeleBot = bot
@@ -174,8 +209,12 @@ class ExceptionHandlerMiddleware(BaseMiddleware):
     # pylint: disable=W0613
     def post_process(self, message: Message, data: dict, exception: Exception | None):
         """Post-process update. Send user an error notification."""
+        self.log.debug('ExceptionHandlerMiddleware.post_process()')
+
         if exception is None:
             return
+
+        self.log.exception('Exception caught during message processing: %s', exception)
         if isinstance(exception, DisplayableException):
             self.bot.reply_to(message, 'Error: ' + str(exception))
         else:

update.py

@@ -1,18 +1,24 @@
+import logging
+from dotenv import load_dotenv
 import os
+
 from rss import RssReader
 from update_manager import UpdateManager
 from database import Database
 from telegram import Notifier
-from dotenv import load_dotenv
 
 load_dotenv()
 
 token = os.getenv('TELEGRAM_TOKEN')
-db_path = os.getenv('DATABASE_PATH')
+db_path = os.getenv('DATABASE_PATH', './bot.db')
+log_level = os.getenv('LOG_LEVEL', 'INFO')
 
-db = Database(db_path)
-notifier = Notifier(token)
-rss_reader = RssReader()
+print('Starting the updater with logging level', log_level.upper())
+logging.basicConfig(level=log_level.upper(), format='%(asctime)s: <%(name)s> [%(levelname)s] %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
 
-updater = UpdateManager(db, notifier, rss_reader)
+db = Database(db_path, logging.getLogger('Database'))
+notifier = Notifier(token, logging.getLogger('Notifier'))
+rss_reader = RssReader(logging.getLogger('RssReader'))
+
+updater = UpdateManager(db, notifier, rss_reader, logging.getLogger('UpdateManager'))
 updater.update()

update_manager.py

@@ -1,3 +1,5 @@
+from logging import Logger
+
 from rss import RssReader, FeedItem
 from database import Database
 from telegram import Notifier
@@ -6,16 +8,24 @@ from telegram import Notifier
 class UpdateManager:
     """Implement the feed update."""
 
-    def __init__(self, database: Database, notifier: Notifier, rss_reader: RssReader) -> None:
+    def __init__(self, database: Database, notifier: Notifier, rss_reader: RssReader, logger: Logger) -> None:
+        self.log: Logger = logger
+        self.log.debug(
+            'UpdateManager.__init__(database=%s, notifier=%s, rss_reader=%s, logger=%s)',
+            database, notifier, rss_reader, logger
+        )
         self.database: Database = database
         self.notifier: Notifier = notifier
         self.rss_reader: RssReader = rss_reader
 
     def update(self):
         """Send new feed items to the user."""
+        self.log.info('Running update')
         feeds = self.database.find_feeds()
+        self.log.info('Feeds to update: %d', len(feeds))
 
         for feed_id, feed_url in feeds:
+            self.log.info('Processing [%d] %s', feed_id, feed_url)
             feed = self.rss_reader.get_feed(feed_url)
             new_items = feed.items
             old_items_urls = self.database.find_feed_items_urls(feed_id)
@@ -31,13 +41,20 @@ class UpdateManager:
 
     def __calculate_difference(self, new_items: list[FeedItem], old_items_urls: list[str]) -> list[FeedItem]:
         """Calculate new feed items."""
+        self.log.debug(
+            '__calculate_difference(new_items=list(%d), old_items_urls=list(%d))', len(new_items), len(old_items_urls)
+        )
         if not old_items_urls:
+            self.log.debug('Old items are empty, returning new')
             return new_items
 
         diff = []
 
+        self.log.debug('Comparing %d new items with %d old', len(new_items), len(old_items_urls))
         for item in new_items:
             if item.url not in old_items_urls:
                 diff.append(item)
 
+        self.log.debug('%d updates found', len(diff))
+
         return diff