diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index c32e635..4ca27e8 100644 --- a/application/Profile/DBProfile.py +++ b/application/Profile/DBProfile.py @@ -20,6 +20,7 @@ import base64 import json +import logging import os import re import uuid @@ -55,6 +56,9 @@ class ActivationType(IntEnum): NORMAL_USER = 1 +logger = logging.getLogger(__name__) + + class DBProfile(Profile): def __init__(self, app): @@ -67,13 +71,21 @@ def __init__(self, app): self.salt = bcrypt.gensalt() # key: user_id, value: activation code - self.activation_cache = TTLCache(maxsize=1024, ttl=ACTIVATION_TTL_SECOND) + size = 1024 + self.activation_cache = TTLCache(maxsize=size, ttl=ACTIVATION_TTL_SECOND) + logger.debug(f"activation_cache set up with {size}, expiration time = {ACTIVATION_TTL_SECOND}") # key: user_id, value: True (to indicate the entry exists; can be any dummy value) - self.resend_cooldown = TTLCache(maxsize=1024, ttl=RESEND_COOLDOWN_TTL_SECOND) + self.resend_cooldown = TTLCache(maxsize=size, ttl=RESEND_COOLDOWN_TTL_SECOND) + logger.debug(f"resend_cooldown cache set up with {size}, expiration time = {RESEND_COOLDOWN_TTL_SECOND}") - with open('/var/www/ictrl/application/resources/activation_email_template.html', 'r') as f: - self.activation_email_body_template = f.read() + activation_email_template = '/var/www/ictrl/application/resources/activation_email_template.html' + logger.debug(f"Opening {activation_email_template} in read-only mode") + try: + with open(activation_email_template, 'r') as f: + self.activation_email_body_template = f.read() + except IOError as e: + logger.error(f"Failed to open {activation_email_template}, does file exist? Error: {e}") class User(db.Model): __table_args__ = {"schema": "ictrl"} @@ -85,8 +97,13 @@ class User(db.Model): @validates('username') def validate_username(self, key, username): - assert re.match("^[A-Za-z0-9_-]+$", username), \ - 'User name should contain only letters, numbers, underscores and dashes' + username_error = 'User name should contain only letters, numbers, underscores and dashes' + try: + assert re.match("^[A-Za-z0-9_-]+$", username) + except AssertionError(username_error) as ae: + logger.error(username_error) + raise ae + return username # this field is for the hashed passwords @@ -97,16 +114,27 @@ def validate_username(self, key, username): @validates('email') def validate_email(self, key, email): - assert re.match(r'\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b', email), \ - f'Invalid email address: "{email}"' + invalid_email_error = f'Invalid email address: "{email}"' + try: + assert re.match(r'\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b', email) + except AssertionError(invalid_email_error) as ae: + logger.error(invalid_email_error) + raise ae # FIXME: remove this utoronto mail restriction in the future - assert email.endswith('utoronto.ca'), "Currently, only Uoft emails are supported" + not_uoft_email_error = "Currently, only UofT emails are supported, emails must end with utoronto.ca" + try: + assert email.endswith('utoronto.ca') + except AssertionError(not_uoft_email_error) as ae: + logger.error(not_uoft_email_error) + raise ae return email activation_type = db.Column(db.Integer, nullable=False, default=ActivationType.NOT_ACTIVATED) + logger.info("Defined a database table: User") + class Session(db.Model): __table_args__ = {"schema": "ictrl"} @@ -118,13 +146,20 @@ class Session(db.Model): @validates('nickname') def validate_nickname(self, key, nickname): - assert len(nickname) <= 8, \ - 'Entered nickname is too long' + nickname_too_long = 'Entered nickname is too long' + try: + assert len(nickname) <= 8 + except AssertionError(nickname_too_long) as ae: + logger.error(nickname_too_long) + raise ae + return nickname username = db.Column(db.String, nullable=False) private_key = db.Column(db.Text, nullable=True) + logger.info("Defined a database table: Session") + class VNCCredentials(db.Model): __table_args__ = {"schema": "ictrl"} @@ -132,6 +167,8 @@ class VNCCredentials(db.Model): nullable=False) credentials = db.Column(db.Text, nullable=False) + logger.info("Defined a database table: VNCCredentials") + self.User = User self.Session = Session self.VNCCredentials = VNCCredentials @@ -139,6 +176,7 @@ class VNCCredentials(db.Model): # db.drop_all() db.engine.execute("CREATE SCHEMA IF NOT EXISTS ictrl;") db.create_all() + logger.info("Created database SCHEMA ictrl and created all databases defined") def login(self, username, password): username = username.lower() @@ -169,7 +207,8 @@ def login(self, username, password): @staticmethod def logout(): # remove the username from the session if it's there - flask_session.pop('userid', None) + userid = flask_session.pop('userid', None) + logger.info(f'Removed session user: {userid}') return True @@ -188,6 +227,8 @@ def query(self): "username": session.username } + logger.info("Query user sessions successful") + return _profile def add_user(self, username, password, email): @@ -236,6 +277,8 @@ def activate_user(self, userid, code): user.activation_type = ActivationType.NORMAL_USER self.save_profile() + logger.info(f"Successfully activated user with userid={userid}") + return True return False @@ -249,6 +292,7 @@ def get_user(self): if user is None: abort(403, 'Cannot find any matching record') + logger.info(f'Successfully retrieved user with userid={userid}') return user def add_session(self, host, username, conn=None): @@ -273,6 +317,8 @@ def add_session(self, host, username, conn=None): session.private_key = f.encrypt(clear_private_key).decode('ascii') self.save_profile() + + logger.info(f'Successfully added a new session: session_id = {session.id}') except AssertionError as e: abort(403, e) except sqlalchemy.exc.IntegrityError as e: @@ -285,6 +331,7 @@ def _get_session(self, session_id): abort(403, 'You are not logged in') userid = flask_session['userid'] + logger.info(f'Returning session, session_id = {session_id}') return self.Session.query.filter_by(id=session_id, user_id=userid).first() def delete_session(self, session_id): @@ -295,6 +342,8 @@ def delete_session(self, session_id): self.db.session.delete(session) self.save_profile() + logger.info(f'Successfully deleted session, session_id = {session_id}') + return True, '' def change_host(self, session_id, new_host): @@ -305,14 +354,18 @@ def change_host(self, session_id, new_host): session.host = new_host self.save_profile() + logger.info(f'Successfully changed host for session, session_id = {session_id}') + return True, '' def save_profile(self): self.db.session.commit() + logger.info("Profile saved") def get_session_info(self, session_id): session = self._get_session(session_id) if session is None: + logger.debug(f"Session {session_id} does not exist, cannot retrieve session info") return None, None, None, None, None f = Fernet(flask_session['session_crypt_key']) @@ -329,6 +382,8 @@ def set_session_nickname(self, session_id, nickname): session.nickname = nickname self.save_profile() + logger.info(f'Successfully set session nickname={nickname} for session {session_id}') + return True, '' def set_session_vnc_credentials(self, session_id, credentials): @@ -340,6 +395,7 @@ def set_session_vnc_credentials(self, session_id, credentials): # it is a delete request vnc_credential = self.VNCCredentials.query.filter_by(session_id=session_id).first() self.db.session.delete(vnc_credential) + logger.info(f'Successfully deleted vnc credentials for session {session_id}') else: # it is an add / update request json_str = json.dumps(credentials) @@ -352,12 +408,14 @@ def set_session_vnc_credentials(self, session_id, credentials): # add vnc_credential = self.VNCCredentials(session_id=session_id, credentials=base64_str) self.db.session.add(vnc_credential) + logger.info(f'Successfully added/updated vnc credentials for session {session_id}') self.save_profile() return True, '' def get_session_vnc_credentials(self, session_id): + logger.debug(f'Getting vnc credentials for session: {session_id}') session = self._get_session(session_id) if session is None: return False, f'failed: session {session_id} does not exist' @@ -389,4 +447,6 @@ def send_activation_email(self, username): expire_min=int(ACTIVATION_TTL_SECOND / 60)) send_email(user.email, 'Activate Your iCtrl Account', body) + logger.info(f'Successfully sent out activation email to email={user.email}') + return True diff --git a/application/Profile/LocalProfile.py b/application/Profile/LocalProfile.py index e7a24c9..774e80b 100644 --- a/application/Profile/LocalProfile.py +++ b/application/Profile/LocalProfile.py @@ -20,6 +20,7 @@ import base64 import copy import json +import logging import uuid from application.paths import * @@ -37,42 +38,57 @@ "sessions": {}, } +logger = logging.getLogger(__name__) + class LocalProfile(Profile): def login(self, username, password): - raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') + not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' + logger.error(not_implemented_error) + raise NotImplementedError(not_implemented_error) @staticmethod def logout(): - raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') + not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' + logger.error(not_implemented_error) + raise NotImplementedError(not_implemented_error) def add_user(self, username, password, email): - raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') + not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' + logger.error(not_implemented_error) + raise NotImplementedError(not_implemented_error) def activate_user(self, userid, code): - raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') + not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' + logger.error(not_implemented_error) + raise NotImplementedError(not_implemented_error) def send_activation_email(self, username): - raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') + not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' + logger.error(not_implemented_error) + raise NotImplementedError(not_implemented_error) def __init__(self): self._profile = copy.deepcopy(_EMPTY_USER_PROFILE) try: + logger.debug(f"Attempting to open file: {USER_PROFILE_PATH}") with open(USER_PROFILE_PATH, "r") as infile: json_data = json.load(infile) if "version" not in json_data or json_data["version"] != _PROFILE_VERSION: - raise ValueError("LocalProfile: Version info not found or mismatch in the profile.") + value_error = "LocalProfile: Version info not found or mismatch in the profile." + logger.error(value_error) + raise ValueError(value_error) self._profile["sessions"] = json_data["sessions"] except Exception as e: self._profile = copy.deepcopy(_EMPTY_USER_PROFILE) - print("LocalProfile: load_profile:", e) - # raise e - print("Unable to load the user profile. Using the default profile instead.") + logger.error(f"LocalProfile: Error loading profile: {e}") + logger.warning("Unable to load the user profile. Using the default profile instead.") def query(self): + logger.info("querying profile") return self._profile def add_session(self, host, username, conn=None): @@ -88,33 +104,41 @@ def add_session(self, host, username, conn=None): status, reason = conn.save_keys(key_filename=this_private_key_path, public_key_comment=this_private_key_path) if not status: + logger.warning(f"Failed to save RSA SSH private key in {this_private_key_path}") return status, reason self.save_profile() + logger.info(f"Successfully saved RSA SSH private key") return True, '' def delete_session(self, session_id): if session_id not in self._profile['sessions']: + logger.error(f"Cannot delete session {session_id}, session does not exist") return False, f'failed: session {session_id} does not exist' try: os.remove(os.path.join(PRIVATE_KEY_PATH, session_id)) except FileNotFoundError: - print('Not valid SSH key found for deletion') + logger.error('Not valid SSH key found for deletion') self._profile['sessions'].pop(session_id) self.save_profile() + logger.info(f'Successfully deleted session {session_id}') + return True, '' def change_host(self, session_id, new_host): if session_id not in self._profile['sessions']: + logger.error(f'Cannot change host, session {session_id} does not exist') return False, f'failed: session {session_id} does not exist' self._profile["sessions"][session_id]['host'] = new_host self.save_profile() + logger.info(f"Successfully changed host for session {session_id} to new host {new_host}") + return True, '' def save_profile(self): @@ -128,6 +152,7 @@ def save_profile(self): def get_session_info(self, session_id): if session_id not in self._profile['sessions']: + logger.error(f"Cannot retrieve session {session_id}, session does not exist") return None, None, None, None, None host = self._profile['sessions'][session_id]['host'] @@ -138,22 +163,28 @@ def get_session_info(self, session_id): else: nickname = None + logger.info(f"Successfully retrieved session info for {session_id}") + return host, username, this_private_key_path, None, nickname def set_session_nickname(self, session_id, nickname): if session_id not in self._profile['sessions']: + logger.error(f"Cannot retrieve session {session_id}, session does not exist") return False, f'failed: session {session_id} does not exist' if len(nickname) > 8: + logger.debug(f"Entered nickname must be under 8 characters") return False, "Entered nickname is too long" if nickname == "": # it is a delete request if 'nickname' in self._profile['sessions'][session_id]: self._profile['sessions'][session_id].pop('nickname') + logger.info(f'Successfully deleted nickname from session {session_id}') else: # it is an add / update request self._profile['sessions'][session_id]['nickname'] = nickname + logger.info(f'Successfully added/updated nickname for session {session_id}') self.save_profile() @@ -161,17 +192,20 @@ def set_session_nickname(self, session_id, nickname): def set_session_vnc_credentials(self, session_id, credentials): if session_id not in self._profile['sessions']: + logger.error(f"Cannot retrieve session {session_id}, session does not exist") return False, f'failed: session {session_id} does not exist' if credentials is None: # it is a delete request if 'vnc_credentials' in self._profile['sessions'][session_id]: self._profile['sessions'][session_id].pop('vnc_credentials') + logger.info(f"Successfully deleted vnc credentials for session {session_id}") else: # it is an add / update request json_str = json.dumps(credentials) base64_str = base64.b64encode(json_str.encode('ascii')).decode('ascii') self._profile['sessions'][session_id]['vnc_credentials'] = base64_str + logger.info(f"Successfully added/updated vnc credentials for session {session_id}") self.save_profile() @@ -179,8 +213,10 @@ def set_session_vnc_credentials(self, session_id, credentials): def get_session_vnc_credentials(self, session_id): if session_id not in self._profile['sessions']: + logger.error(f"Cannot retrieve session {session_id}, session does not exist") return False, f'failed: session {session_id} does not exist' + logger.info(f"Retrieving vnc credentials for session {session_id}") if 'vnc_credentials' in self._profile['sessions'][session_id]: json_str = base64.b64decode(self._profile['sessions'][session_id]['vnc_credentials']) return True, json.loads(json_str.decode('ascii')) @@ -192,4 +228,6 @@ class DummyUser: id = 0 dummy_user = DummyUser() + + logger.info(f'Returning user: {dummy_user}') return dummy_user diff --git a/application/__init__.py b/application/__init__.py index 160468a..e3a7742 100644 --- a/application/__init__.py +++ b/application/__init__.py @@ -34,6 +34,7 @@ print("Logging setup failed with exception = ", ex) logger = logging.getLogger(__name__) +#Setting the message to warning in case logging set up from dictConfig was not successful logger.warning(f"Logging is set up with config={config}") from .Profile.Profile import Profile @@ -73,7 +74,7 @@ def handle_after_request(response: Flask.response_class): APP_PORT = int(sys.argv[1]) LOCAL_AUTH_KEY = sys.argv[2] except IndexError: - print("Debug mode") + logger.debug("Running in debug mode") APP_PORT = 5000 LOCAL_AUTH_KEY = '' diff --git a/application/paths.py b/application/paths.py index 4148177..2e355f4 100644 --- a/application/paths.py +++ b/application/paths.py @@ -18,13 +18,18 @@ # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +import logging import os import platform +logger = logging.getLogger(__name__) + + def makedir_if_not_exists(path): if not os.path.exists(path): os.mkdir(path) + logger.info(f'Created directory, path = {path}') # setup profile path @@ -33,7 +38,9 @@ def makedir_if_not_exists(path): elif platform.system() == "Darwin" or 'Linux': PROFILE_PATH = os.path.join(os.path.expanduser("~"), ".ictrl") else: - raise SystemError(f"Operating System: {platform.system()} not supported") + error = f"Operating System: {platform.system()} not supported" + logger.error(error) + raise SystemError(error) makedir_if_not_exists(PROFILE_PATH) USER_PROFILE_PATH = os.path.join(PROFILE_PATH, "user_profile.json") diff --git a/application/utils.py b/application/utils.py index ea5f53a..1e7c1a3 100644 --- a/application/utils.py +++ b/application/utils.py @@ -18,6 +18,7 @@ # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +import logging import os import smtplib import socket @@ -25,6 +26,9 @@ from email.mime.text import MIMEText +logger = logging.getLogger(__name__) + + def int_to_bytes(num): return bytes([num]) @@ -32,7 +36,9 @@ def int_to_bytes(num): def find_free_port(): with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock: sock.bind(('', 0)) - return sock.getsockname()[1] + socket_info = sock.getsockname() + logger.info(f"Socket binded to address {socket_info[0]} at port {socket_info[1]}") + return socket_info[1] def send_email(to_email, subject, body): @@ -53,6 +59,9 @@ def send_email(to_email, subject, body): server_ssl.login(sender_email, sender_password) server_ssl.sendmail(sender_email, to_email, msg.as_string()) + + logger.info(f'Successfully sent email from {sender_email} to {to_email}') + server_ssl.close() @@ -77,6 +86,7 @@ def validate_password(password): reason = f'Password should have at least one of the symbols [{"".join(special_symbols)}]' if reason is not None: + logger.error(f'Failed to validate password, reason: {reason}') return False, reason else: return True, None @@ -91,6 +101,8 @@ def get_headers_dict_from_str(headers_str): header_name, header_value = line.split(': ', 1) headers[header_name] = header_value + logger.debug(f'Extracted HTTP headers, headers = {headers}') + return headers