From fa6f8112022855c3c770f60da60c61344a37be81 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Sat, 27 Jul 2024 01:04:39 -0400 Subject: [PATCH 01/12] Logging setup in DBProfile.py and minor changes in application init --- application/Profile/DBProfile.py | 135 ++++++++++++++++++++++++------- application/__init__.py | 1 + 2 files changed, 108 insertions(+), 28 deletions(-) diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index c32e635..4d5c458 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,12 @@ 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' + try: + assert re.match("^[A-Za-z0-9_-]+$", username) + except AssertionError as ae: + logger.error("User name should contain only letters, numbers, underscores and dashes") + raise ae + return username # this field is for the hashed passwords @@ -97,16 +113,25 @@ 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}"' + try: + assert re.match(r'\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b', email) + except AssertionError as ae: + logger.error(f'Invalid email address: "{email}"') + raise ae # FIXME: remove this utoronto mail restriction in the future - assert email.endswith('utoronto.ca'), "Currently, only Uoft emails are supported" + try: + assert email.endswith('utoronto.ca') + except AssertionError as ae: + logger.error(f"Currently, only UofT emails are supported, emails must end with utoronto.ca") + 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 +143,19 @@ class Session(db.Model): @validates('nickname') def validate_nickname(self, key, nickname): - assert len(nickname) <= 8, \ - 'Entered nickname is too long' + try: + assert len(nickname) <= 8 + except AssertionError as ae: + logger.error('Entered nickname is 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 +163,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,21 +172,27 @@ 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() password_bytes = password.encode('ascii') user = self.User.query.filter_by(username=username).first() - if user is None: - abort(403, 'ACCOUNT_WRONG_USERNAME') + hashed_password_bytes = user.password.encode('ascii') + if (user is None) or (not bcrypt.checkpw(password_bytes, hashed_password_bytes)): + #Reason being is for security concern, we want to be as ambiguous as possible + #In a scenario a hacker wants to hack into an account + #You wouldn't want him to know whether your username or your password is correct + #If he guesses the username then he can guess the password next, given by the original error messages + error_msg = 'ACCOUNT_WRONG_USERNAME or ACCOUNT_WRONG_PASSWORD' + logger.error(error_msg) + abort(403, error_msg) if user.activation_type == ActivationType.NOT_ACTIVATED: - abort(401, 'ACCOUNT_NOT_ACTIVATED') - - hashed_password_bytes = user.password.encode('ascii') - if not bcrypt.checkpw(password_bytes, hashed_password_bytes): - abort(403, 'ACCOUNT_WRONG_PASSWORD') + error_msg = 'ACCOUNT_NOT_ACTIVATED' + logger.error(error_msg) + abort(401, error_msg) flask_session.clear() flask_session['userid'] = user.id @@ -169,7 +208,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 +228,8 @@ def query(self): "username": session.username } + logger.info("Query user sessions successful") + return _profile def add_user(self, username, password, email): @@ -197,6 +239,7 @@ def add_user(self, username, password, email): password_ok, password_reason = validate_password(password) if not password_ok: + logger.warning(f'Password is not allowed, reason: {password_reason}') abort(422, password_reason) # hash the password before storing @@ -215,10 +258,15 @@ def add_user(self, username, password, email): except sqlalchemy.exc.IntegrityError as e: error_info = e.orig.args[0] if 'user_username_key' in error_info: - abort(422, 'ACCOUNT_DUPLICATE_USERNAME') + error = 'Failed to add user: ACCOUNT_DUPLICATE_USERNAME' + logger.error(error) + abort(422, error) elif 'user_email_key' in error_info: - abort(422, 'ACCOUNT_DUPLICATE_EMAIL') + error = 'Failed to add user: ACCOUNT_DUPLICATE_EMAIL' + logger .error(error) + abort(422, error) + logger.error('Failed to add user: other reasons') abort(403, e) return True, '' @@ -231,24 +279,33 @@ def activate_user(self, userid, code): elif cached_code == code: user = self.User.query.filter_by(id=userid).first() if user is None: - abort(403, f'Cannot find any matching user with userid={userid}') + error = f'Cannot find any matching user with userid={userid}' + logger.error(error) + abort(403, error) user.activation_type = ActivationType.NORMAL_USER self.save_profile() + logger.info(f"Successfully activated user with userid={userid}") + return True return False def get_user(self): if 'userid' not in flask_session: - abort(403, 'You are not logged in') + error = 'You are not logged in' + logger.error(error) + abort(403, error) userid = flask_session['userid'] user = self.User.query.filter_by(id=userid).first() if user is None: - abort(403, 'Cannot find any matching record') + error = f'Cannot find any matching record: userid = {userid}' + logger.error(error) + abort(403, error) + logger.info(f'Successfully retrieved user with userid={userid}') return user def add_session(self, host, username, conn=None): @@ -273,18 +330,25 @@ 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: + logger.error(f'Error: {e}') abort(403, e) except sqlalchemy.exc.IntegrityError as e: + logger.error(f'Error: {e}') abort(403, e) return True, '' def _get_session(self, session_id): if 'userid' not in flask_session: - abort(403, 'You are not logged in') + error = 'You are not logged in' + logger.error(error) + abort(403, error) 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 +359,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 +371,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 +399,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 +412,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,6 +425,7 @@ 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() @@ -372,10 +446,13 @@ def get_session_vnc_credentials(self, session_id): def send_activation_email(self, username): user = self.User.query.filter_by(username=username).first() if user is None: - abort(403, f'Cannot find any matching user with username={username}') + error = f'Cannot find any matching user with username={username}' + logger.error(error) + abort(403, error) elif self.resend_cooldown.get(str(user.id), None): - abort(429, f'Too soon to resend. Please check your email junk box or try again in ' - f'{RESEND_COOLDOWN_TTL_SECOND} seconds. ') + error = f'Too soon to resend. Please check your email junk box or try again in {RESEND_COOLDOWN_TTL_SECOND} seconds.' + logger.error(error) + abort(429, error) user_id = str(user.id) code = str(uuid.uuid4()) @@ -389,4 +466,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/__init__.py b/application/__init__.py index 2040aba..3f7f160 100644 --- a/application/__init__.py +++ b/application/__init__.py @@ -33,6 +33,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 From b692a390f7389427d7c18b6f4dfe96e13e75c1f6 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Sat, 27 Jul 2024 20:16:21 -0400 Subject: [PATCH 02/12] Logging setup in LocalProfile.py and minor changes in DBProfile.py --- application/Profile/DBProfile.py | 1 + application/Profile/LocalProfile.py | 58 ++++++++++++++++++++++++----- 2 files changed, 49 insertions(+), 10 deletions(-) diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index 4d5c458..7b3c6fe 100644 --- a/application/Profile/DBProfile.py +++ b/application/Profile/DBProfile.py @@ -432,6 +432,7 @@ def set_session_vnc_credentials(self, session_id, credentials): 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' diff --git a/application/Profile/LocalProfile.py b/application/Profile/LocalProfile.py index e7a24c9..2471e4e 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"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 From 4a48a1fbe07df48914263fd1f34b5980e4266bf7 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Sat, 27 Jul 2024 22:00:02 -0400 Subject: [PATCH 03/12] Logging setup in general application python files --- application/__init__.py | 2 +- application/paths.py | 9 ++++++++- application/utils.py | 15 ++++++++++++++- 3 files changed, 23 insertions(+), 3 deletions(-) diff --git a/application/__init__.py b/application/__init__.py index 3f7f160..8ade24f 100644 --- a/application/__init__.py +++ b/application/__init__.py @@ -55,7 +55,7 @@ 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..54dd378 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 @@ -106,6 +118,7 @@ def local_auth(headers, abort_func): auth_passed = False if not auth_passed: + logger.debug('Authentication failed, you are not authorized to access this API.') abort_func(403, "You are not authorized to access this API.") return auth_passed From fea6f8fa3387e7af9da88ce4ab1471ba6da81571 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Sun, 8 Sep 2024 12:38:01 -0400 Subject: [PATCH 04/12] Reverted logging changes before abort --- application/Profile/DBProfile.py | 54 +++++++++----------------------- application/utils.py | 1 - 2 files changed, 15 insertions(+), 40 deletions(-) diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index 7b3c6fe..b98f576 100644 --- a/application/Profile/DBProfile.py +++ b/application/Profile/DBProfile.py @@ -180,19 +180,15 @@ def login(self, username, password): user = self.User.query.filter_by(username=username).first() hashed_password_bytes = user.password.encode('ascii') - if (user is None) or (not bcrypt.checkpw(password_bytes, hashed_password_bytes)): - #Reason being is for security concern, we want to be as ambiguous as possible - #In a scenario a hacker wants to hack into an account - #You wouldn't want him to know whether your username or your password is correct - #If he guesses the username then he can guess the password next, given by the original error messages - error_msg = 'ACCOUNT_WRONG_USERNAME or ACCOUNT_WRONG_PASSWORD' - logger.error(error_msg) - abort(403, error_msg) + if user is None: + abort(403, 'ACCOUNT_WRONG_USERNAME') if user.activation_type == ActivationType.NOT_ACTIVATED: - error_msg = 'ACCOUNT_NOT_ACTIVATED' - logger.error(error_msg) - abort(401, error_msg) + abort(401, 'ACCOUNT_NOT_ACTIVATED') + + hashed_password_bytes = user.password.encode('ascii') + if not bcrypt.checkpw(password_bytes, hashed_password_bytes): + abort(403, 'ACCOUNT_WRONG_PASSWORD') flask_session.clear() flask_session['userid'] = user.id @@ -239,7 +235,6 @@ def add_user(self, username, password, email): password_ok, password_reason = validate_password(password) if not password_ok: - logger.warning(f'Password is not allowed, reason: {password_reason}') abort(422, password_reason) # hash the password before storing @@ -258,15 +253,10 @@ def add_user(self, username, password, email): except sqlalchemy.exc.IntegrityError as e: error_info = e.orig.args[0] if 'user_username_key' in error_info: - error = 'Failed to add user: ACCOUNT_DUPLICATE_USERNAME' - logger.error(error) - abort(422, error) + abort(422, 'Failed to add user: ACCOUNT_DUPLICATE_USERNAME') elif 'user_email_key' in error_info: - error = 'Failed to add user: ACCOUNT_DUPLICATE_EMAIL' - logger .error(error) - abort(422, error) + abort(422, 'Failed to add user: ACCOUNT_DUPLICATE_EMAIL') - logger.error('Failed to add user: other reasons') abort(403, e) return True, '' @@ -279,9 +269,7 @@ def activate_user(self, userid, code): elif cached_code == code: user = self.User.query.filter_by(id=userid).first() if user is None: - error = f'Cannot find any matching user with userid={userid}' - logger.error(error) - abort(403, error) + abort(403, f'Cannot find any matching user with userid={userid}') user.activation_type = ActivationType.NORMAL_USER self.save_profile() @@ -294,16 +282,12 @@ def activate_user(self, userid, code): def get_user(self): if 'userid' not in flask_session: - error = 'You are not logged in' - logger.error(error) - abort(403, error) + abort(403, 'You are not logged in') userid = flask_session['userid'] user = self.User.query.filter_by(id=userid).first() if user is None: - error = f'Cannot find any matching record: userid = {userid}' - logger.error(error) - abort(403, error) + abort(403, f'Cannot find any matching record: userid = {userid}') logger.info(f'Successfully retrieved user with userid={userid}') return user @@ -333,19 +317,15 @@ def add_session(self, host, username, conn=None): logger.info(f'Successfully added a new session: session_id = {session.id}') except AssertionError as e: - logger.error(f'Error: {e}') abort(403, e) except sqlalchemy.exc.IntegrityError as e: - logger.error(f'Error: {e}') abort(403, e) return True, '' def _get_session(self, session_id): if 'userid' not in flask_session: - error = 'You are not logged in' - logger.error(error) - abort(403, error) + abort(403, 'You are not logged in') userid = flask_session['userid'] logger.info(f'Returning session, session_id = {session_id}') @@ -447,13 +427,9 @@ def get_session_vnc_credentials(self, session_id): def send_activation_email(self, username): user = self.User.query.filter_by(username=username).first() if user is None: - error = f'Cannot find any matching user with username={username}' - logger.error(error) - abort(403, error) + abort(403, f'Cannot find any matching user with username={username}') elif self.resend_cooldown.get(str(user.id), None): - error = f'Too soon to resend. Please check your email junk box or try again in {RESEND_COOLDOWN_TTL_SECOND} seconds.' - logger.error(error) - abort(429, error) + abort(429, f'Too soon to resend. Please check your email junk box or try again in {RESEND_COOLDOWN_TTL_SECOND} seconds.') user_id = str(user.id) code = str(uuid.uuid4()) diff --git a/application/utils.py b/application/utils.py index 54dd378..1e7c1a3 100644 --- a/application/utils.py +++ b/application/utils.py @@ -118,7 +118,6 @@ def local_auth(headers, abort_func): auth_passed = False if not auth_passed: - logger.debug('Authentication failed, you are not authorized to access this API.') abort_func(403, "You are not authorized to access this API.") return auth_passed From 56362562376bf397cf7c38d3359bd3ee19625c1f Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Sun, 8 Sep 2024 13:35:24 -0400 Subject: [PATCH 05/12] reverted changes made to abort calls --- application/Profile/DBProfile.py | 30 ++++++++++++++++------------- application/Profile/LocalProfile.py | 2 +- 2 files changed, 18 insertions(+), 14 deletions(-) diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index b98f576..4ca27e8 100644 --- a/application/Profile/DBProfile.py +++ b/application/Profile/DBProfile.py @@ -97,10 +97,11 @@ class User(db.Model): @validates('username') def validate_username(self, key, username): + username_error = 'User name should contain only letters, numbers, underscores and dashes' try: assert re.match("^[A-Za-z0-9_-]+$", username) - except AssertionError as ae: - logger.error("User name should contain only letters, numbers, underscores and dashes") + except AssertionError(username_error) as ae: + logger.error(username_error) raise ae return username @@ -113,17 +114,19 @@ def validate_username(self, key, username): @validates('email') def validate_email(self, key, 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 as ae: - logger.error(f'Invalid email address: "{email}"') + except AssertionError(invalid_email_error) as ae: + logger.error(invalid_email_error) raise ae # FIXME: remove this utoronto mail restriction in the future + not_uoft_email_error = "Currently, only UofT emails are supported, emails must end with utoronto.ca" try: assert email.endswith('utoronto.ca') - except AssertionError as ae: - logger.error(f"Currently, only UofT emails are supported, emails must end with utoronto.ca") + except AssertionError(not_uoft_email_error) as ae: + logger.error(not_uoft_email_error) raise ae return email @@ -143,10 +146,11 @@ class Session(db.Model): @validates('nickname') def validate_nickname(self, key, nickname): + nickname_too_long = 'Entered nickname is too long' try: assert len(nickname) <= 8 - except AssertionError as ae: - logger.error('Entered nickname is too long') + except AssertionError(nickname_too_long) as ae: + logger.error(nickname_too_long) raise ae return nickname @@ -179,7 +183,6 @@ def login(self, username, password): password_bytes = password.encode('ascii') user = self.User.query.filter_by(username=username).first() - hashed_password_bytes = user.password.encode('ascii') if user is None: abort(403, 'ACCOUNT_WRONG_USERNAME') @@ -253,9 +256,9 @@ def add_user(self, username, password, email): except sqlalchemy.exc.IntegrityError as e: error_info = e.orig.args[0] if 'user_username_key' in error_info: - abort(422, 'Failed to add user: ACCOUNT_DUPLICATE_USERNAME') + abort(422, 'ACCOUNT_DUPLICATE_USERNAME') elif 'user_email_key' in error_info: - abort(422, 'Failed to add user: ACCOUNT_DUPLICATE_EMAIL') + abort(422, 'ACCOUNT_DUPLICATE_EMAIL') abort(403, e) @@ -287,7 +290,7 @@ def get_user(self): user = self.User.query.filter_by(id=userid).first() if user is None: - abort(403, f'Cannot find any matching record: userid = {userid}') + abort(403, 'Cannot find any matching record') logger.info(f'Successfully retrieved user with userid={userid}') return user @@ -429,7 +432,8 @@ def send_activation_email(self, username): if user is None: abort(403, f'Cannot find any matching user with username={username}') elif self.resend_cooldown.get(str(user.id), None): - abort(429, f'Too soon to resend. Please check your email junk box or try again in {RESEND_COOLDOWN_TTL_SECOND} seconds.') + abort(429, f'Too soon to resend. Please check your email junk box or try again in ' + f'{RESEND_COOLDOWN_TTL_SECOND} seconds. ') user_id = str(user.id) code = str(uuid.uuid4()) diff --git a/application/Profile/LocalProfile.py b/application/Profile/LocalProfile.py index 2471e4e..774e80b 100644 --- a/application/Profile/LocalProfile.py +++ b/application/Profile/LocalProfile.py @@ -84,7 +84,7 @@ def __init__(self): except Exception as e: self._profile = copy.deepcopy(_EMPTY_USER_PROFILE) - logger.error(f"Error loading profile: {e}") + logger.error(f"LocalProfile: Error loading profile: {e}") logger.warning("Unable to load the user profile. Using the default profile instead.") def query(self): From bcb03e04db37a65a92f152030bc69e92e69adb22 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Thu, 26 Dec 2024 18:23:29 -0500 Subject: [PATCH 06/12] minor changes from the code review for PR #35 --- application/Profile/LocalProfile.py | 25 +++++++++++++------------ 1 file changed, 13 insertions(+), 12 deletions(-) diff --git a/application/Profile/LocalProfile.py b/application/Profile/LocalProfile.py index 774e80b..f178cd9 100644 --- a/application/Profile/LocalProfile.py +++ b/application/Profile/LocalProfile.py @@ -25,6 +25,7 @@ from application.paths import * from .Profile import Profile +from typing import Any, Dict, Tuple _PROFILE_VERSION = 1 # in case the schema changes in the future @@ -87,11 +88,11 @@ def __init__(self): logger.error(f"LocalProfile: Error loading profile: {e}") logger.warning("Unable to load the user profile. Using the default profile instead.") - def query(self): + def query(self) -> Dict[str, Any]: logger.info("querying profile") return self._profile - def add_session(self, host, username, conn=None): + def add_session(self, host, username, conn=None) -> Tuple[bool, str]: session = copy.deepcopy(_EMPTY_SESSION) session_id = uuid.uuid4().hex @@ -104,15 +105,15 @@ 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}") + 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") + logger.info('Successfully saved RSA SSH private key') return True, '' - def delete_session(self, session_id): + def delete_session(self, session_id) -> Tuple[bool, str]: 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' @@ -120,7 +121,7 @@ def delete_session(self, session_id): try: os.remove(os.path.join(PRIVATE_KEY_PATH, session_id)) except FileNotFoundError: - logger.error('Not valid SSH key found for deletion') + logger.exception('No valid SSH key found for deletion') self._profile['sessions'].pop(session_id) self.save_profile() @@ -129,7 +130,7 @@ def delete_session(self, session_id): return True, '' - def change_host(self, session_id, new_host): + def change_host(self, session_id, new_host) -> Tuple[bool, str]: 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' @@ -150,7 +151,7 @@ def save_profile(self): # need to handle any write permission issues, once observed raise e - def get_session_info(self, session_id): + def get_session_info(self, session_id) -> Tuple[Any, Any, Any, None, Any]: 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 @@ -167,13 +168,13 @@ def get_session_info(self, session_id): return host, username, this_private_key_path, None, nickname - def set_session_nickname(self, session_id, nickname): + def set_session_nickname(self, session_id, nickname) -> Tuple[bool, str]: 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") + logger.debug('Entered nickname must be under 8 characters') return False, "Entered nickname is too long" if nickname == "": @@ -190,7 +191,7 @@ def set_session_nickname(self, session_id, nickname): return True, '' - def set_session_vnc_credentials(self, session_id, credentials): + def set_session_vnc_credentials(self, session_id, credentials) -> Tuple[bool, str]: 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' @@ -211,7 +212,7 @@ def set_session_vnc_credentials(self, session_id, credentials): return True, '' - def get_session_vnc_credentials(self, session_id): + def get_session_vnc_credentials(self, session_id) -> Tuple[bool, Any]: 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' From b6c07567b8ba3acbe20c208cf14bb88b366e3292 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Fri, 27 Dec 2024 02:51:44 -0500 Subject: [PATCH 07/12] changes made according to code review --- application/Profile/DBProfile.py | 34 +++++++++++------------------ application/Profile/LocalProfile.py | 19 ++++++++-------- 2 files changed, 22 insertions(+), 31 deletions(-) diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index 4ca27e8..b48fdf0 100644 --- a/application/Profile/DBProfile.py +++ b/application/Profile/DBProfile.py @@ -73,19 +73,19 @@ def __init__(self, app): # key: user_id, value: activation code 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}") + logger.debug("activation_cache set up with %d, expiration time = %d", size, ACTIVATION_TTL_SECOND) # key: user_id, value: True (to indicate the entry exists; can be any dummy value) 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}") + logger.debug("resend_cooldown cache set up with %d, expiration time = %d", size, RESEND_COOLDOWN_TTL_SECOND) activation_email_template = '/var/www/ictrl/application/resources/activation_email_template.html' - logger.debug(f"Opening {activation_email_template} in read-only mode") + logger.debug("Opening %s in read-only mode", activation_email_template) try: - with open(activation_email_template, 'r') as f: + with open(activation_email_template) 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}") + logger.exception(f"Failed to open {activation_email_template}, does file exist? Error: {e}") class User(db.Model): __table_args__ = {"schema": "ictrl"} @@ -98,11 +98,9 @@ class User(db.Model): @validates('username') def validate_username(self, key, username): 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: + if not re.match("^[A-Za-z0-9_-]+$", username): logger.error(username_error) - raise ae + raise AssertionError(username_error) return username @@ -115,19 +113,15 @@ def validate_username(self, key, username): @validates('email') def validate_email(self, key, 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: + if not re.match(r'\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b', email): logger.error(invalid_email_error) - raise ae + raise AssertionError(invalid_email_error) # FIXME: remove this utoronto mail restriction in the future 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: + if not email.endswith('utoronto.ca'): logger.error(not_uoft_email_error) - raise ae + raise AssertionError(not_uoft_email_error) return email @@ -147,11 +141,9 @@ class Session(db.Model): @validates('nickname') def validate_nickname(self, key, nickname): nickname_too_long = 'Entered nickname is too long' - try: - assert len(nickname) <= 8 - except AssertionError(nickname_too_long) as ae: + if len(nickname) > 8: logger.error(nickname_too_long) - raise ae + raise AssertionError(nickname_too_long) return nickname diff --git a/application/Profile/LocalProfile.py b/application/Profile/LocalProfile.py index f178cd9..8db465a 100644 --- a/application/Profile/LocalProfile.py +++ b/application/Profile/LocalProfile.py @@ -25,7 +25,6 @@ from application.paths import * from .Profile import Profile -from typing import Any, Dict, Tuple _PROFILE_VERSION = 1 # in case the schema changes in the future @@ -88,11 +87,11 @@ def __init__(self): logger.error(f"LocalProfile: Error loading profile: {e}") logger.warning("Unable to load the user profile. Using the default profile instead.") - def query(self) -> Dict[str, Any]: + def query(self) -> dict[str, object]: logger.info("querying profile") return self._profile - def add_session(self, host, username, conn=None) -> Tuple[bool, str]: + def add_session(self, host, username, conn=None) -> tuple[bool, str]: session = copy.deepcopy(_EMPTY_SESSION) session_id = uuid.uuid4().hex @@ -113,7 +112,7 @@ def add_session(self, host, username, conn=None) -> Tuple[bool, str]: logger.info('Successfully saved RSA SSH private key') return True, '' - def delete_session(self, session_id) -> Tuple[bool, str]: + def delete_session(self, session_id) -> tuple[bool, str]: 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' @@ -130,7 +129,7 @@ def delete_session(self, session_id) -> Tuple[bool, str]: return True, '' - def change_host(self, session_id, new_host) -> Tuple[bool, str]: + def change_host(self, session_id, new_host) -> tuple[bool, str]: 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' @@ -151,7 +150,7 @@ def save_profile(self): # need to handle any write permission issues, once observed raise e - def get_session_info(self, session_id) -> Tuple[Any, Any, Any, None, Any]: + def get_session_info(self, session_id) -> tuple[object, object, object, None, object]: 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 @@ -168,7 +167,7 @@ def get_session_info(self, session_id) -> Tuple[Any, Any, Any, None, Any]: return host, username, this_private_key_path, None, nickname - def set_session_nickname(self, session_id, nickname) -> Tuple[bool, str]: + def set_session_nickname(self, session_id, nickname) -> tuple[bool, str]: 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' @@ -191,7 +190,7 @@ def set_session_nickname(self, session_id, nickname) -> Tuple[bool, str]: return True, '' - def set_session_vnc_credentials(self, session_id, credentials) -> Tuple[bool, str]: + def set_session_vnc_credentials(self, session_id, credentials) -> tuple[bool, str]: 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' @@ -212,7 +211,7 @@ def set_session_vnc_credentials(self, session_id, credentials) -> Tuple[bool, st return True, '' - def get_session_vnc_credentials(self, session_id) -> Tuple[bool, Any]: + def get_session_vnc_credentials(self, session_id) -> tuple[bool, object]: 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' @@ -224,7 +223,7 @@ def get_session_vnc_credentials(self, session_id) -> Tuple[bool, Any]: else: return True, '' - def get_user(self): + def get_user(self) -> object: class DummyUser: id = 0 From 55c57cad582cfb07bcb941d8fa0befbc4ae23a58 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Fri, 27 Dec 2024 14:50:37 -0500 Subject: [PATCH 08/12] change logging statements to use the %s operator instead of f-strings --- application/Profile/DBProfile.py | 28 +++++++++++----------- application/Profile/LocalProfile.py | 36 ++++++++++++++--------------- 2 files changed, 32 insertions(+), 32 deletions(-) diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index b48fdf0..988d141 100644 --- a/application/Profile/DBProfile.py +++ b/application/Profile/DBProfile.py @@ -85,7 +85,7 @@ def __init__(self, app): with open(activation_email_template) as f: self.activation_email_body_template = f.read() except IOError as e: - logger.exception(f"Failed to open {activation_email_template}, does file exist? Error: {e}") + logger.exception("Failed to open %s, does file exist? Error: %s", activation_email_template, e) class User(db.Model): __table_args__ = {"schema": "ictrl"} @@ -200,7 +200,7 @@ def login(self, username, password): def logout(): # remove the username from the session if it's there userid = flask_session.pop('userid', None) - logger.info(f'Removed session user: {userid}') + logger.info("Removed session user: %s", userid) return True @@ -269,7 +269,7 @@ def activate_user(self, userid, code): user.activation_type = ActivationType.NORMAL_USER self.save_profile() - logger.info(f"Successfully activated user with userid={userid}") + logger.info("Successfully activated user with userid=%s", userid) return True @@ -284,7 +284,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}') + logger.info("Successfully retrieved user with userid=%s", userid) return user def add_session(self, host, username, conn=None): @@ -310,7 +310,7 @@ def add_session(self, host, username, conn=None): self.save_profile() - logger.info(f'Successfully added a new session: session_id = {session.id}') + logger.info("Successfully added a new session: session_id = %s", session.id) except AssertionError as e: abort(403, e) except sqlalchemy.exc.IntegrityError as e: @@ -323,7 +323,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}') + logger.info("Returning session, session_id = %s", session_id) return self.Session.query.filter_by(id=session_id, user_id=userid).first() def delete_session(self, session_id): @@ -334,7 +334,7 @@ def delete_session(self, session_id): self.db.session.delete(session) self.save_profile() - logger.info(f'Successfully deleted session, session_id = {session_id}') + logger.info("Successfully deleted session, session_id = %s", session_id) return True, '' @@ -346,7 +346,7 @@ 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}') + logger.info("Successfully changed host for session, session_id = %s", session_id) return True, '' @@ -357,7 +357,7 @@ def save_profile(self): 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") + logger.debug("Session %s does not exist, cannot retrieve session info", session_id) return None, None, None, None, None f = Fernet(flask_session['session_crypt_key']) @@ -374,7 +374,7 @@ 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}') + logger.info("Successfully set session nickname=%s for session %s", nickname, session_id) return True, '' @@ -387,7 +387,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}') + logger.info("Successfully deleted vnc credentials for session %s", session_id) else: # it is an add / update request json_str = json.dumps(credentials) @@ -400,14 +400,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}') + logger.info("Successfully added/updated vnc credentials for session %s", 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}') + logger.debug("Getting vnc credentials for session: %s", session_id) session = self._get_session(session_id) if session is None: return False, f'failed: session {session_id} does not exist' @@ -439,6 +439,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}') + logger.info("Successfully sent out activation email to email=%s", user.email) return True diff --git a/application/Profile/LocalProfile.py b/application/Profile/LocalProfile.py index 8db465a..8537222 100644 --- a/application/Profile/LocalProfile.py +++ b/application/Profile/LocalProfile.py @@ -71,7 +71,7 @@ def send_activation_email(self, username): def __init__(self): self._profile = copy.deepcopy(_EMPTY_USER_PROFILE) try: - logger.debug(f"Attempting to open file: {USER_PROFILE_PATH}") + logger.debug("Attempting to open file: %s", USER_PROFILE_PATH) with open(USER_PROFILE_PATH, "r") as infile: json_data = json.load(infile) @@ -104,7 +104,7 @@ def add_session(self, host, username, conn=None) -> tuple[bool, str]: 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}') + logger.warning("Failed to save RSA SSH private key in %s", this_private_key_path) return status, reason self.save_profile() @@ -114,7 +114,7 @@ def add_session(self, host, username, conn=None) -> tuple[bool, str]: def delete_session(self, session_id) -> tuple[bool, str]: if session_id not in self._profile['sessions']: - logger.error(f"Cannot delete session {session_id}, session does not exist") + logger.error('Cannot delete session %s, session does not exist', session_id) return False, f'failed: session {session_id} does not exist' try: @@ -125,19 +125,19 @@ def delete_session(self, session_id) -> tuple[bool, str]: self._profile['sessions'].pop(session_id) self.save_profile() - logger.info(f'Successfully deleted session {session_id}') + logger.info("Successfully deleted session %s", session_id) return True, '' def change_host(self, session_id, new_host) -> tuple[bool, str]: if session_id not in self._profile['sessions']: - logger.error(f'Cannot change host, session {session_id} does not exist') + logger.error("Cannot change host, session %s does not exist", session_id) 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}") + logger.info("Successfully changed host for session %s to new host %s", session_id, new_host) return True, '' @@ -152,7 +152,7 @@ def save_profile(self): def get_session_info(self, session_id) -> tuple[object, object, object, None, object]: if session_id not in self._profile['sessions']: - logger.error(f"Cannot retrieve session {session_id}, session does not exist") + logger.error("Cannot retrieve session %s, session does not exist", session_id) return None, None, None, None, None host = self._profile['sessions'][session_id]['host'] @@ -163,28 +163,28 @@ def get_session_info(self, session_id) -> tuple[object, object, object, None, ob else: nickname = None - logger.info(f"Successfully retrieved session info for {session_id}") + logger.info("Successfully retrieved session info for %s", session_id) return host, username, this_private_key_path, None, nickname def set_session_nickname(self, session_id, nickname) -> tuple[bool, str]: if session_id not in self._profile['sessions']: - logger.error(f"Cannot retrieve session {session_id}, session does not exist") + logger.error("Cannot retrieve session %s, session does not exist", session_id) return False, f'failed: session {session_id} does not exist' if len(nickname) > 8: - logger.debug('Entered nickname must be under 8 characters') + logger.debug("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}') + logger.info("Successfully deleted nickname from session %s", 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}') + logger.info("Successfully added/updated nickname for session %s", session_id) self.save_profile() @@ -192,20 +192,20 @@ def set_session_nickname(self, session_id, nickname) -> tuple[bool, str]: def set_session_vnc_credentials(self, session_id, credentials) -> tuple[bool, str]: if session_id not in self._profile['sessions']: - logger.error(f"Cannot retrieve session {session_id}, session does not exist") + logger.error("Cannot retrieve session %s, session does not exist", session_id) 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}") + logger.info("Successfully deleted vnc credentials for session %s", 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}") + logger.info("Successfully added/updated vnc credentials for session %s", session_id) self.save_profile() @@ -213,10 +213,10 @@ def set_session_vnc_credentials(self, session_id, credentials) -> tuple[bool, st def get_session_vnc_credentials(self, session_id) -> tuple[bool, object]: if session_id not in self._profile['sessions']: - logger.error(f"Cannot retrieve session {session_id}, session does not exist") + logger.error("Cannot retrieve session %s, session does not exist", session_id) return False, f'failed: session {session_id} does not exist' - logger.info(f"Retrieving vnc credentials for session {session_id}") + logger.info("Retrieving vnc credentials for session %s", 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')) @@ -229,5 +229,5 @@ class DummyUser: dummy_user = DummyUser() - logger.info(f'Returning user: {dummy_user}') + logger.info("Returning user: %s", dummy_user) return dummy_user From edccf85c83216756f72acc87484fa6a130e0c8a2 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Fri, 27 Dec 2024 15:07:31 -0500 Subject: [PATCH 09/12] changed logging statements to use %s operators in application/utils.py --- application/utils.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/application/utils.py b/application/utils.py index 1e7c1a3..c7d4e9f 100644 --- a/application/utils.py +++ b/application/utils.py @@ -37,7 +37,7 @@ def find_free_port(): with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock: sock.bind(('', 0)) socket_info = sock.getsockname() - logger.info(f"Socket binded to address {socket_info[0]} at port {socket_info[1]}") + logger.info("Socket binded to address %s at port %s", socket_info[0], socket_info[1]) return socket_info[1] @@ -60,7 +60,7 @@ def send_email(to_email, subject, body): server_ssl.sendmail(sender_email, to_email, msg.as_string()) - logger.info(f'Successfully sent email from {sender_email} to {to_email}') + logger.info('Successfully sent email from %s to %s', sender_email, to_email) server_ssl.close() @@ -86,7 +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}') + logger.error('Failed to validate password, reason: %s', reason) return False, reason else: return True, None From a86f91f2fb2aadab0c29f989b2449f0f93845ef3 Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Fri, 27 Dec 2024 15:34:15 -0500 Subject: [PATCH 10/12] Updated utils.py based on code review --- application/utils.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/application/utils.py b/application/utils.py index c7d4e9f..f82fd8d 100644 --- a/application/utils.py +++ b/application/utils.py @@ -86,7 +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('Failed to validate password, reason: %s', reason) + logger.warning('Failed to validate password, reason: %s', reason) return False, reason else: return True, None @@ -101,7 +101,7 @@ 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}') + logger.debug(f'Extracted HTTP headers, headers = %s', headers) return headers From 49d84fc4c7d3f2753da2c92880092eb3d24e0bed Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Fri, 27 Dec 2024 15:37:27 -0500 Subject: [PATCH 11/12] Minor change from code review --- application/utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/application/utils.py b/application/utils.py index f82fd8d..ad6918b 100644 --- a/application/utils.py +++ b/application/utils.py @@ -101,7 +101,7 @@ 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 = %s', headers) + logger.debug('Extracted HTTP headers, headers = %s', headers) return headers From 72097f00e893954e6ef9f21fe85f3847eae56ecb Mon Sep 17 00:00:00 2001 From: Ruihao Li Date: Tue, 7 Jan 2025 02:12:37 -0500 Subject: [PATCH 12/12] Logging changes based on code review --- application/Profile/DBProfile.py | 33 +++++++++++++---------------- application/Profile/LocalProfile.py | 26 +++++++---------------- application/__init__.py | 5 ++++- application/paths.py | 7 +++--- application/utils.py | 4 ++++ 5 files changed, 34 insertions(+), 41 deletions(-) diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index 988d141..1aded79 100644 --- a/application/Profile/DBProfile.py +++ b/application/Profile/DBProfile.py @@ -41,7 +41,9 @@ from .Profile import Profile from ..utils import send_email, validate_password +ACTIVATION_EMAIL_TEMPLATE = '/var/www/ictrl/application/resources/activation_email_template.html' ACTIVATION_TTL_SECOND = 60 * 30 +MAX_PENDING_ACTIVATION_NUM = 1024 RESEND_COOLDOWN_TTL_SECOND = 30 SESSION_CRYPT_SALT = b'>@\x05[N%\xcf]+\x82\xc3\xcd\xde\xa6a\xeb' @@ -71,21 +73,17 @@ def __init__(self, app): self.salt = bcrypt.gensalt() # key: user_id, value: activation code - size = 1024 - self.activation_cache = TTLCache(maxsize=size, ttl=ACTIVATION_TTL_SECOND) - logger.debug("activation_cache set up with %d, expiration time = %d", size, ACTIVATION_TTL_SECOND) + self.activation_cache = TTLCache(maxsize=MAX_PENDING_ACTIVATION_NUM, ttl=ACTIVATION_TTL_SECOND) # key: user_id, value: True (to indicate the entry exists; can be any dummy value) - self.resend_cooldown = TTLCache(maxsize=size, ttl=RESEND_COOLDOWN_TTL_SECOND) - logger.debug("resend_cooldown cache set up with %d, expiration time = %d", size, RESEND_COOLDOWN_TTL_SECOND) + self.resend_cooldown = TTLCache(maxsize=MAX_PENDING_ACTIVATION_NUM, ttl=RESEND_COOLDOWN_TTL_SECOND) - activation_email_template = '/var/www/ictrl/application/resources/activation_email_template.html' - logger.debug("Opening %s in read-only mode", activation_email_template) try: - with open(activation_email_template) as f: + with open(ACTIVATION_EMAIL_TEMPLATE) as f: self.activation_email_body_template = f.read() - except IOError as e: - logger.exception("Failed to open %s, does file exist? Error: %s", activation_email_template, e) + except OSError as e: + logger.exception('Failed to open "%s"', ACTIVATION_EMAIL_TEMPLATE) + raise e class User(db.Model): __table_args__ = {"schema": "ictrl"} @@ -168,7 +166,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") + logger.info("Database initialization is done.") def login(self, username, password): username = username.lower() @@ -200,7 +198,7 @@ def login(self, username, password): def logout(): # remove the username from the session if it's there userid = flask_session.pop('userid', None) - logger.info("Removed session user: %s", userid) + logger.info("Removed user session: %s", userid) return True @@ -219,7 +217,7 @@ def query(self): "username": session.username } - logger.info("Query user sessions successful") + logger.info("Query user sessions successful, all user sessions:\n%s", json.dumps(_profile)) return _profile @@ -310,7 +308,7 @@ def add_session(self, host, username, conn=None): self.save_profile() - logger.info("Successfully added a new session: session_id = %s", session.id) + logger.info("Successfully added a new session: session_id=%s", session.id) except AssertionError as e: abort(403, e) except sqlalchemy.exc.IntegrityError as e: @@ -323,7 +321,6 @@ def _get_session(self, session_id): abort(403, 'You are not logged in') userid = flask_session['userid'] - logger.info("Returning session, session_id = %s", session_id) return self.Session.query.filter_by(id=session_id, user_id=userid).first() def delete_session(self, session_id): @@ -334,7 +331,7 @@ def delete_session(self, session_id): self.db.session.delete(session) self.save_profile() - logger.info("Successfully deleted session, session_id = %s", session_id) + logger.info("Successfully deleted session, session_id=%s", session_id) return True, '' @@ -346,7 +343,7 @@ def change_host(self, session_id, new_host): session.host = new_host self.save_profile() - logger.info("Successfully changed host for session, session_id = %s", session_id) + logger.info("Successfully changed host for session, session_id=%s", session_id) return True, '' @@ -357,7 +354,7 @@ def save_profile(self): def get_session_info(self, session_id): session = self._get_session(session_id) if session is None: - logger.debug("Session %s does not exist, cannot retrieve session info", session_id) + logger.debug("Cannot retrieve session info: session_id=%s", session_id) return None, None, None, None, None f = Fernet(flask_session['session_crypt_key']) diff --git a/application/Profile/LocalProfile.py b/application/Profile/LocalProfile.py index 8537222..7422134 100644 --- a/application/Profile/LocalProfile.py +++ b/application/Profile/LocalProfile.py @@ -43,30 +43,20 @@ class LocalProfile(Profile): def login(self, username, password): - not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' - logger.error(not_implemented_error) - raise NotImplementedError(not_implemented_error) + raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') @staticmethod def logout(): - not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' - logger.error(not_implemented_error) - raise NotImplementedError(not_implemented_error) + raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') def add_user(self, username, password, email): - not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' - logger.error(not_implemented_error) - raise NotImplementedError(not_implemented_error) + raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') def activate_user(self, userid, code): - not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' - logger.error(not_implemented_error) - raise NotImplementedError(not_implemented_error) + raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') def send_activation_email(self, username): - not_implemented_error = f'Method {__name__} should not be invoke from {__class__}' - logger.error(not_implemented_error) - raise NotImplementedError(not_implemented_error) + raise NotImplementedError(f'Method {__name__} should not be invoke from {__class__}') def __init__(self): self._profile = copy.deepcopy(_EMPTY_USER_PROFILE) @@ -84,7 +74,7 @@ def __init__(self): except Exception as e: self._profile = copy.deepcopy(_EMPTY_USER_PROFILE) - logger.error(f"LocalProfile: Error loading profile: {e}") + logger.exception('LocalProfile: Error loading profile: %s', e) logger.warning("Unable to load the user profile. Using the default profile instead.") def query(self) -> dict[str, object]: @@ -173,7 +163,7 @@ def set_session_nickname(self, session_id, nickname) -> tuple[bool, str]: return False, f'failed: session {session_id} does not exist' if len(nickname) > 8: - logger.debug("Entered nickname must be under 8 characters") + logger.error("Entered nickname must be under 8 characters") return False, "Entered nickname is too long" if nickname == "": @@ -229,5 +219,5 @@ class DummyUser: dummy_user = DummyUser() - logger.info("Returning user: %s", dummy_user) + logger.debug("Returning user: %s", dummy_user) return dummy_user diff --git a/application/__init__.py b/application/__init__.py index e3a7742..a8df7ff 100644 --- a/application/__init__.py +++ b/application/__init__.py @@ -35,7 +35,10 @@ 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}") +if 'config' in locals() and config is not None: + logger.warning("Logging is set up with config=%s", config) +else: + logger.warning("Logging config is None") from .Profile.Profile import Profile diff --git a/application/paths.py b/application/paths.py index 2e355f4..cb78236 100644 --- a/application/paths.py +++ b/application/paths.py @@ -29,7 +29,7 @@ def makedir_if_not_exists(path): if not os.path.exists(path): os.mkdir(path) - logger.info(f'Created directory, path = {path}') + logger.info('Created directory, path = %s', path) # setup profile path @@ -38,9 +38,8 @@ def makedir_if_not_exists(path): elif platform.system() == "Darwin" or 'Linux': PROFILE_PATH = os.path.join(os.path.expanduser("~"), ".ictrl") else: - error = f"Operating System: {platform.system()} not supported" - logger.error(error) - raise SystemError(error) + logger.error("Operating System: %s not supported", platform.system()) + raise SystemError(f"Operating System: {platform.system()} not supported") 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 ad6918b..a577422 100644 --- a/application/utils.py +++ b/application/utils.py @@ -34,6 +34,10 @@ def int_to_bytes(num): def find_free_port(): + """ + Binds a socket on a random free port and returns it. + :return: int - The free port number. + """ with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock: sock.bind(('', 0)) socket_info = sock.getsockname()