From 6ac26106377ac2149d18d513727ad9e028e40b9a Mon Sep 17 00:00:00 2001 From: Alexey Skobkin Date: Sun, 10 Jul 2022 15:07:26 +0300 Subject: [PATCH] Logging added (#34) Reviewed-on: https://git.skobk.in/Miroslavsckaya/tg_rss_bot/pulls/34 Reviewed-by: Miroslavsckaya Co-authored-by: Alexey Skobkin Co-committed-by: Alexey Skobkin --- bot.py | 15 ++++++++++---- database.py | 30 +++++++++++++++++++++++---- rss.py | 8 +++++++ telegram.py | 53 ++++++++++++++++++++++++++++++++++++++++------- update.py | 23 ++++++++++++++------ update_manager.py | 19 ++++++++++++++++- 6 files changed, 126 insertions(+), 22 deletions(-) diff --git a/bot.py b/bot.py index 6cc7d6b..f215ab1 100644 --- a/bot.py +++ b/bot.py @@ -9,10 +9,17 @@ 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() diff --git a/database.py b/database.py index 72136f4..83908b3 100644 --- a/database.py +++ b/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))' ) diff --git a/rss.py b/rss.py index 02f9dad..eeeaa01 100644 --- a/rss.py +++ b/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)) diff --git a/telegram.py b/telegram.py index aecb49e..7860b45 100644 --- a/telegram.py +++ b/telegram.py @@ -1,6 +1,7 @@ import time from bleach.sanitizer import Cleaner +from logging import Logger from telebot import TeleBot from telebot.handler_backends import BaseMiddleware from telebot.types import Message @@ -14,26 +15,33 @@ 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): # pylint: disable=unused-argument + self.log.debug('__command_help(message=\'%s\', data=\'%s\')', message, data) self.bot.reply_to( message, 'Supported commands:\n' @@ -44,19 +52,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 = '' @@ -66,15 +78,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.') @@ -96,7 +111,9 @@ 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) self.html_sanitizer: Cleaner = Cleaner( tags=['b', 'strong', 'i', 'em', 'u', 'ins', 's', 'strike', 'del', 'span', 'tg-spoiler', 'a', 'code', 'pre'], @@ -107,10 +124,17 @@ class Notifier: 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, @@ -122,6 +146,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), @@ -129,9 +154,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 @@ -151,22 +178,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 @@ -175,7 +208,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 @@ -186,8 +221,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: diff --git a/update.py b/update.py index 48dca8d..4714c24 100644 --- a/update.py +++ b/update.py @@ -1,18 +1,29 @@ +import logging import os +from dotenv import load_dotenv + 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() diff --git a/update_manager.py b/update_manager.py index c8898f2..9ff5218 100644 --- a/update_manager.py +++ b/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