From b40be62cb14a89981395b56c0b13e7f3f55461a0 Mon Sep 17 00:00:00 2001 From: Frank Becker Date: Sat, 8 Feb 2020 22:16:19 +0100 Subject: [PATCH] use logging for console output --- bot.py | 94 ++++++++++++++++++-------------- modules/bot.py | 10 ++-- modules/common/module.py | 6 +- modules/common/pollingservice.py | 10 ++-- modules/cron.py | 1 + modules/googlecal.py | 42 ++++++-------- modules/ig.py | 7 +-- modules/loc.py | 7 ++- modules/teamup.py | 11 ++-- modules/twitter.py | 4 +- modules/url.py | 6 +- 11 files changed, 101 insertions(+), 97 deletions(-) diff --git a/bot.py b/bot.py index a033fb4..2509190 100755 --- a/bot.py +++ b/bot.py @@ -9,6 +9,7 @@ import re import sys import traceback import urllib.parse +import logging from importlib import reload import requests @@ -28,14 +29,30 @@ class CommandRequiresOwner(Exception): class Bot: - appid = 'org.vranki.hemppa' - version = '1.2' - client = None - join_on_invite = False - modules = dict() - pollcount = 0 - poll_task = None - owners = [] + + def __init__(self): + self.appid = 'org.vranki.hemppa' + self.version = '1.2' + self.client = None + self.join_on_invite = False + self.modules = dict() + self.pollcount = 0 + self.poll_task = None + self.owners = [] + self.debug = os.getenv("DEBUG") + + self.initializeLogger() + self.logger = logging.getLogger("hemppa") + self.logger.debug("Initialized") + + def initializeLogger(self): + log_format = '%(levelname)s - %(name)s - %(message)s' + if self.debug: + logging.root.setLevel(logging.DEBUG) + else: + logging.root.setLevel(logging.INFO) + + logging.basicConfig(format=log_format) async def send_text(self, room, body): msg = { @@ -130,11 +147,10 @@ class Bot: except CommandRequiresOwner: await self.send_text(room, f'Sorry, only bot owner can run that command.') except Exception: - await self.send_text(room, - f'Module {command} experienced difficulty: {sys.exc_info()[0]} - see log for details') + await self.send_text(room, f'Module {command} experienced difficulty: {sys.exc_info()[0]} - see log for details') traceback.print_exc(file=sys.stderr) else: - print(f"Unknown command: {command}") + self.logger.error(f"Unknown command: {command}") # TODO Make this configurable # await self.send_text(room, # f"Sorry. I don't know what to do. Execute !help to get a list of available commands.") @@ -152,31 +168,28 @@ class Bot: for attempt in range(3): result = await self.client.join(room.room_id) if type(result) == JoinError: - print(f"Error joining room {room.room_id} (attempt %d): %s", - attempt, result.message, - ) + self.logger.error(f"Error joining room %s (attempt %d): %s", room.room_id, attempt, result.message) else: - print(f"joining room '{room.display_name}'({room.room_id}) invited by '{event.sender}'") + self.logger.info(f"joining room '{room.display_name}'({room.room_id}) invited by '{event.sender}'") break else: - print( - f'Received invite event, but not joining as sender is not owner or bot not configured to join on invite. {event}') + self.logger.warning(f'Received invite event, but not joining as sender is not owner or bot not configured to join on invite. {event}') def load_module(self, modulename): try: - print("load module: " + modulename) + self.logger.info(f'load module: {modulename}') module = importlib.import_module('modules.' + modulename) module = reload(module) cls = getattr(module, 'MatrixModule') return cls(modulename) except ModuleNotFoundError: - print('Module ', modulename, ' failed to load!') + self.logger.error(f'Module {modulename} failed to load!') traceback.print_exc(file=sys.stderr) return None def reload_modules(self): for modulename in bot.modules: - print('Reloading', modulename, '..') + self.logger.info(f'Reloading {modulename} ..') self.modules[modulename] = self.load_module(modulename) self.load_settings(self.get_account_data()) @@ -213,7 +226,7 @@ class Bot: self.__handle_error_response(response) if response.status_code != 200: - print('Setting account data failed:', response, response.json()) + self.logger.error('Setting account data failed. response: %s json: %s', response, response.json()) def get_account_data(self): userid = urllib.parse.quote(self.matrix_user) @@ -225,14 +238,13 @@ class Bot: if response.status_code == 200: return response.json() - print( - f'Getting account data failed: {response} {response.json()} - this is normal if you have not saved any settings yet.') + self.logger.error(f'Getting account data failed: {response} {response.json()} - this is normal if you have not saved any settings yet.') return None def __handle_error_response(self, response): if response.status_code == 401: - print("ERROR: access token is invalid or missing") - print("NOTE: check MATRIX_ACCESS_TOKEN or set MATRIX_PASSWORD") + self.logger.error("access token is invalid or missing") + self.logger.info("NOTE: check MATRIX_ACCESS_TOKEN or set MATRIX_PASSWORD") sys.exit(2) def init(self): @@ -250,7 +262,7 @@ class Bot: if self.client.access_token is None: if self.matrix_pass is None: - print("Either MATRIX_ACCESS_TOKEN or MATRIX_PASSWORD need to be set") + self.logger.error("Either MATRIX_ACCESS_TOKEN or MATRIX_PASSWORD need to be set") sys.exit(1) self.join_on_invite = join_on_invite is not None @@ -258,13 +270,13 @@ class Bot: self.get_modules() else: - print("The environment variables MATRIX_SERVER, MATRIX_USER and BOT_OWNERS are mandatory") + self.logger.error("The environment variables MATRIX_SERVER, MATRIX_USER and BOT_OWNERS are mandatory") sys.exit(1) def start(self): self.load_settings(self.get_account_data()) enabled_modules = [module for module_name, module in self.modules.items() if module.enabled] - print(f'Starting {len(enabled_modules)} modules..') + self.logger.info(f'Starting {len(enabled_modules)} modules..') for modulename, moduleobject in self.modules.items(): if moduleobject.enabled: try: @@ -273,7 +285,7 @@ class Bot: traceback.print_exc(file=sys.stderr) def stop(self): - print(f'Stopping {len(self.modules)} modules..') + self.logger.info(f'Stopping {len(self.modules)} modules..') for modulename, moduleobject in self.modules.items(): try: moduleobject.matrix_stop(bot) @@ -285,18 +297,18 @@ class Bot: login_response = await self.client.login(self.matrix_pass) if isinstance(login_response, LoginError): - print(f"Failed to login: {login_response.message}") + self.logger.error(f"Failed to login: {login_response.message}") return last_16 = self.client.access_token[-16:] - print(f"Logged in with password, access token: ...{last_16}") + self.logger.info(f"Logged in with password, access token: ...{last_16}") await self.client.sync() for roomid, room in self.client.rooms.items(): - print(f"Bot is on '{room.display_name}'({roomid}) with {len(room.users)} users") + self.logger.info(f"Bot is on '{room.display_name}'({roomid}) with {len(room.users)} users") if len(room.users) == 1: - print(f'Room {roomid} has no other users - leaving it.') - print(await self.client.room_leave(roomid)) + self.logger.info(f'Room {roomid} has no other users - leaving it.') + self.logger.info(await self.client.room_leave(roomid)) self.start() @@ -308,12 +320,12 @@ class Bot: self.client.add_event_callback(self.invite_cb, (InviteEvent,)) if self.join_on_invite: - print('Note: Bot will join rooms if invited') - print('Bot running as', self.client.user, ', owners', self.owners) + self.logger.info('Note: Bot will join rooms if invited') + self.logger.info('Bot running as %s, owners %s', self.client.user, self.owners) self.bot_task = asyncio.create_task(self.client.sync_forever(timeout=30000)) await self.bot_task else: - print('Client was not able to log in, check env variables!') + self.logger.error('Client was not able to log in, check env variables!') async def shutdown(self): @@ -321,16 +333,16 @@ class Bot: logout = await self.client.logout() if isinstance(logout, LogoutResponse): - print("Logout successful") + self.logger.info("Logout successful") try: await self.client.close() - print("Connection closed") + self.logger.info("Connection closed") except Exception as e: - print("error while closing client", e) + self.logger.error("error while closing client: %s", e) else: logout: LogoutError - print(f"Logout unsuccessful. msg: {logout.message}") + self.logger.error(f"Logout unsuccessful. msg: {logout.message}") else: await self.client.client_session.close() diff --git a/modules/bot.py b/modules/bot.py index 8c23dc2..3b3515e 100644 --- a/modules/bot.py +++ b/modules/bot.py @@ -48,7 +48,7 @@ class MatrixModule(BotModule): async def leave(self, bot, room, event): bot.must_be_admin(room, event) - print(f'{event.sender} asked bot to leave room {room.room_id}') + self.logger.info(f'{event.sender} asked bot to leave room {room.room_id}') await bot.send_text(room, f'By your command.') await bot.client.room_leave(room.room_id) @@ -89,13 +89,12 @@ class MatrixModule(BotModule): async def quit(self, bot, room, event): bot.must_be_admin(room, event) await bot.send_text(room, f'Quitting, as requested') - print(f'{event.sender} commanded bot to quit, so quitting..') + self.logger.info(f'{event.sender} commanded bot to quit, so quitting..') bot.bot_task.cancel() async def enable_module(self, bot, room, event, module_name): bot.must_be_admin(room, event) - print(f"asked to enable {module_name}") - + self.logger.info(f"asked to enable {module_name}") if bot.modules.get(module_name): module = bot.modules.get(module_name) module.enable() @@ -107,8 +106,7 @@ class MatrixModule(BotModule): async def disable_module(self, bot, room, event, module_name): bot.must_be_admin(room, event) - print(f"asked to disable {module_name}") - + self.logger.info(f"asked to disable {module_name}") if bot.modules.get(module_name): module = bot.modules.get(module_name) if module.can_be_disabled: diff --git a/modules/common/module.py b/modules/common/module.py index 78728a3..975233f 100644 --- a/modules/common/module.py +++ b/modules/common/module.py @@ -1,3 +1,4 @@ +import logging from abc import ABC, abstractmethod from nio import RoomMessageText, MatrixRoom @@ -30,6 +31,7 @@ class BotModule(ABC): self.enabled = True self.can_be_disabled = True self.name = name + self.logger = logging.getLogger("module " + self.name) def matrix_start(self, bot): """Called once on startup @@ -37,7 +39,7 @@ class BotModule(ABC): :param bot: a reference to the bot :type bot: Bot """ - print('Starting', self.name, '..') + self.logger.info('Starting..') @abstractmethod async def matrix_message(self, bot, room, event): @@ -58,7 +60,7 @@ class BotModule(ABC): :param bot: a reference to the bot :type bot: Bot """ - print('Stopping', self.name, '..') + self.logger.info('Stopping..') async def matrix_poll(self, bot, pollcount): """Called every 10 seconds diff --git a/modules/common/pollingservice.py b/modules/common/pollingservice.py index d51b5e3..c8da02f 100644 --- a/modules/common/pollingservice.py +++ b/modules/common/pollingservice.py @@ -33,7 +33,7 @@ class PollingService(BotModule): for account in accounts: await self.poll_account(bot, account, roomid, send_messages) else: - print(f'Bot is no longer in room {roomid} - deleting it from {self.service_name} room list') + self.logger.warning(f'Bot is no longer in room {roomid} - deleting it from {self.service_name} room list') delete_rooms.append(roomid) for roomid in delete_rooms: self.account_rooms.pop(roomid, None) @@ -62,7 +62,7 @@ class PollingService(BotModule): f"Next poll in this room at {self.next_poll_time.get(room.room_id)} - in {self.next_poll_time.get(room.room_id) - datetime.now()}") elif args[1] == 'poll': bot.must_be_owner(event) - print(f'{self.service_name} force polling requested by {event.sender}') + self.logger.info(f'{self.service_name} force polling requested by {event.sender}') # Faking next poll times to force poll for roomid in self.account_rooms: self.next_poll_time[roomid] = datetime.now() - timedelta(hours=1) @@ -77,7 +77,7 @@ class PollingService(BotModule): bot.must_be_admin(room, event) account = args[2] - print(f'Adding {self.service_name} account {account} to room id {room.room_id}') + self.logger.info(f'Adding {self.service_name} account {account} to room id {room.room_id}') if self.account_rooms.get(room.room_id): if account not in self.account_rooms[room.room_id]: @@ -94,12 +94,12 @@ class PollingService(BotModule): bot.must_be_admin(room, event) account = args[2] - print(f'Removing {self.service_name} account {account} from room id {room.room_id}') + self.logger.info(f'Removing {self.service_name} account {account} from room id {room.room_id}') if self.account_rooms.get(room.room_id): self.account_rooms[room.room_id].remove(account) - print(f'{self.service_name} accounts now for this room {self.account_rooms.get(room.room_id)}') + self.logger.info(f'{self.service_name} accounts now for this room {self.account_rooms.get(room.room_id)}') bot.save_settings() await bot.send_text(room, f'Removed {self.service_name} account from this room') diff --git a/modules/cron.py b/modules/cron.py index 24e8c16..4dc4052 100644 --- a/modules/cron.py +++ b/modules/cron.py @@ -1,5 +1,6 @@ import shlex from datetime import datetime + from .common.module import BotModule diff --git a/modules/googlecal.py b/modules/googlecal.py index ccfb6c1..37b7817 100644 --- a/modules/googlecal.py +++ b/modules/googlecal.py @@ -9,7 +9,6 @@ from google.auth.transport.requests import Request from google_auth_oauthlib.flow import InstalledAppFlow from googleapiclient.discovery import build - # # Google calendar notifications # @@ -40,10 +39,10 @@ class MatrixModule(BotModule): if os.path.exists('token.pickle'): with open('token.pickle', 'rb') as token: creds = pickle.load(token) - print('Loaded existing pickle file') + self.logger.info('Loaded existing pickle file') # If there are no (valid) credentials available, let the user log in. if not creds or not creds.valid: - print('No credentials or credentials not valid!') + self.logger.warn('No credentials or credentials not valid!') if creds and creds.expired and creds.refresh_token: creds.refresh(Request()) else: @@ -53,19 +52,17 @@ class MatrixModule(BotModule): # Save the credentials for the next run with open('token.pickle', 'wb') as token: pickle.dump(creds, token) - print('Pickle saved') + self.logger.info('Pickle saved') self.service = build('calendar', 'v3', credentials=creds) try: - calendar_list = self.service.calendarList().list().execute()[ - 'items'] - print( - f'Google calendar set up successfully with access to {len(calendar_list)} calendars:\n') + calendar_list = self.service.calendarList().list().execute()['items'] + self.logger.info(f'Google calendar set up successfully with access to {len(calendar_list)} calendars:\n') for calendar in calendar_list: - print(calendar['summary'] + ' - ' + calendar['id']) + self.logger.info(f"{calendar['summary']} - + {calendar['id']}") except Exception: - print('Getting calendar list failed!') + self.logger.error('Getting calendar list failed!') async def matrix_message(self, bot, room, event): if not self.service: @@ -78,7 +75,7 @@ class MatrixModule(BotModule): if len(args) == 2: if args[1] == 'today': for calid in calendars: - print('Listing events in cal', calid) + self.logger.info(f'Listing events in cal {calid}') events = events + self.list_today(calid) if args[1] == 'list': await bot.send_text(room, 'Calendars in this room: ' + str(self.calendar_rooms.get(room.room_id))) @@ -89,7 +86,7 @@ class MatrixModule(BotModule): bot.must_be_admin(room, event) calid = args[2] - print(f'Adding calendar {calid} to room id {room.room_id}') + self.logger.info(f'Adding calendar {calid} to room id {room.room_id}') if self.calendar_rooms.get(room.room_id): if calid not in self.calendar_rooms[room.room_id]: @@ -100,8 +97,7 @@ class MatrixModule(BotModule): else: self.calendar_rooms[room.room_id] = [calid] - print( - f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') + self.logger.info(f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') bot.save_settings() @@ -112,13 +108,12 @@ class MatrixModule(BotModule): bot.must_be_admin(room, event) calid = args[2] - print(f'Removing calendar {calid} from room id {room.room_id}') + self.logger.info(f'Removing calendar {calid} from room id {room.room_id}') if self.calendar_rooms.get(room.room_id): self.calendar_rooms[room.room_id].remove(calid) - print( - f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') + self.logger.info(f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') bot.save_settings() @@ -127,14 +122,14 @@ class MatrixModule(BotModule): else: for calid in calendars: - print('Listing events in cal', calid) + self.logger.info(f'Listing events in cal {calid}') events = events + self.list_upcoming(calid) if len(events) > 0: - print(f'Found {len(events)} events') + self.logger.info(f'Found {len(events)} events') await self.send_events(bot, events, room) else: - print(f'No events found') + self.logger.info(f'No events found') await bot.send_text(room, 'No events found, try again later :)') async def send_events(self, bot, events, room): @@ -154,19 +149,18 @@ class MatrixModule(BotModule): def list_today(self, calid): startTime = datetime.utcnow() - startTime = startTime.replace( - hour=0, minute=0, second=0, microsecond=0) + startTime = startTime.replace(hour=0, minute=0, second=0, microsecond=0) endTime = startTime + timedelta(hours=24) now = startTime.isoformat() + 'Z' end = endTime.isoformat() + 'Z' - print('Looking for events between', now, end) + self.logger.info(f'Looking for events between {now} {end}') events_result = self.service.events().list(calendarId=calid, timeMin=now, timeMax=end, maxResults=10, singleEvents=True, orderBy='startTime').execute() return events_result.get('items', []) def help(self): - return ('Google calendar. Lists 10 next events by default. today = list today\'s events.') + return 'Google calendar. Lists 10 next events by default. today = list today\'s events.' def get_settings(self): data = super().get_settings() diff --git a/modules/ig.py b/modules/ig.py index 7ec3e46..09d9764 100644 --- a/modules/ig.py +++ b/modules/ig.py @@ -19,7 +19,7 @@ class MatrixModule(PollingService): async def poll_implementation(self, bot, account, roomid, send_messages): try: medias = self.instagram.get_medias(account, 5) - print(f'Polling instagram account {account} for room {roomid} - got {len(medias)} posts.') + self.logger.info(f'Polling instagram account {account} for room {roomid} - got {len(medias)} posts.') for media in medias: if send_messages: if media.identifier not in self.known_ids: @@ -29,12 +29,11 @@ class MatrixModule(PollingService): self.known_ids.add(media.identifier) except InstagramNotFoundException: - print('ig error: there is ', account, - ' account that does not exist - deleting from room') + self.logger.error(f"{account} does not exist - deleting from room") self.account_rooms[roomid].remove(account) bot.save_settings() except Exception: - print('Polling instagram account failed:') + self.logger.error('Polling instagram account failed:') traceback.print_exc(file=sys.stderr) polldelay = timedelta(minutes=30 + randrange(30)) diff --git a/modules/loc.py b/modules/loc.py index 8f0c475..ffa7679 100644 --- a/modules/loc.py +++ b/modules/loc.py @@ -1,5 +1,6 @@ from geopy.geocoders import Nominatim -from nio import RoomMessageUnknown, AsyncClient +from nio import RoomMessageUnknown + from modules.common.module import BotModule @@ -50,9 +51,9 @@ class MatrixModule(BotModule): else: query = event.body[4:] geolocator = Nominatim(user_agent=bot.appid) - print('loc: looking up', query, '..') + self.logger.info('loc: looking up %s ..', query) location = geolocator.geocode(query) - print('loc rx', location) + self.logger.info('loc rx %s', location) if location: locationmsg = { "body": str(location.address), diff --git a/modules/teamup.py b/modules/teamup.py index c2bc421..4189cf9 100644 --- a/modules/teamup.py +++ b/modules/teamup.py @@ -3,7 +3,6 @@ from datetime import datetime from pyteamup import Calendar - # # TeamUp calendar notifications # @@ -48,7 +47,7 @@ class MatrixModule(BotModule): bot.must_be_admin(room, event) calid = args[2] - print(f'Adding calendar {calid} to room id {room.room_id}') + self.logger.info(f'Adding calendar {calid} to room id {room.room_id}') if self.calendar_rooms.get(room.room_id): if calid not in self.calendar_rooms[room.room_id]: @@ -59,8 +58,7 @@ class MatrixModule(BotModule): else: self.calendar_rooms[room.room_id] = [calid] - print( - f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') + self.logger.info(f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') bot.save_settings() self.setup_calendars() @@ -69,13 +67,12 @@ class MatrixModule(BotModule): bot.must_be_admin(room, event) calid = args[2] - print(f'Removing calendar {calid} from room id {room.room_id}') + self.logger.info(f'Removing calendar {calid} from room id {room.room_id}') if self.calendar_rooms.get(room.room_id): self.calendar_rooms[room.room_id].remove(calid) - print( - f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') + self.logger.info(f'Calendars now for this room {self.calendar_rooms.get(room.room_id)}') bot.save_settings() self.setup_calendars() diff --git a/modules/twitter.py b/modules/twitter.py index 0582ea7..49f20bb 100644 --- a/modules/twitter.py +++ b/modules/twitter.py @@ -16,7 +16,7 @@ class MatrixModule(PollingService): async def poll_implementation(self, bot, account, roomid, send_messages): try: tweets = query_tweets_from_user(account, limit=1) - print(f'Polling twitter account {account} - got {len(tweets)} tweets') + self.logger.info(f'Polling twitter account {account} - got {len(tweets)} tweets') for tweet in tweets: if tweet.tweet_id not in self.known_ids: if send_messages: @@ -25,5 +25,5 @@ class MatrixModule(PollingService): f'Twitter {account}: {tweet.text} - https://twitter.com{tweet.tweet_url}') self.known_ids.add(tweet.tweet_id) except Exception: - print('Polling twitter account failed:') + self.logger.error('Polling twitter account failed:') traceback.print_exc(file=sys.stderr) diff --git a/modules/url.py b/modules/url.py index 597638b..9221f34 100644 --- a/modules/url.py +++ b/modules/url.py @@ -100,11 +100,11 @@ class MatrixModule(BotModule): try: r = httpx.get(url) except Exception as e: - print(f"Failed fetching url {url}. Error: {e}") + self.logger.error(f"Failed fetching url {url}. Error: {e}") return (title, description) if r.status_code != 200: - print(f"Failed fetching url {url}. Status code: {r.status_code}") + self.logger.info(f"Failed fetching url {url}. Status code: {r.status_code}") return (title, description) # try parse and get the title @@ -115,7 +115,7 @@ class MatrixModule(BotModule): if descr_tag: description = descr_tag.get("content", None) except Exception as e: - print(f"Failed parsing response from url {url}. Error: {e}") + self.logger.error(f"Failed parsing response from url {url}. Error: {e}") return (title, description) return (title, description)