diff --git a/application/Profile/DBProfile.py b/application/Profile/DBProfile.py index c32e635..1aded79 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 @@ -40,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' @@ -55,6 +58,9 @@ class ActivationType(IntEnum): NORMAL_USER = 1 +logger = logging.getLogger(__name__) + + class DBProfile(Profile): def __init__(self, app): @@ -67,13 +73,17 @@ def __init__(self, app): self.salt = bcrypt.gensalt() # key: user_id, value: activation code - self.activation_cache = TTLCache(maxsize=1024, ttl=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=1024, ttl=RESEND_COOLDOWN_TTL_SECOND) + self.resend_cooldown = TTLCache(maxsize=MAX_PENDING_ACTIVATION_NUM, ttl=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() + try: + with open(ACTIVATION_EMAIL_TEMPLATE) as f: + self.activation_email_body_template = f.read() + except OSError as e: + logger.exception('Failed to open "%s"', ACTIVATION_EMAIL_TEMPLATE) + raise e class User(db.Model): __table_args__ = {"schema": "ictrl"} @@ -85,8 +95,11 @@ 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' + if not re.match("^[A-Za-z0-9_-]+$", username): + logger.error(username_error) + raise AssertionError(username_error) + return username # this field is for the hashed passwords @@ -97,16 +110,23 @@ 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}"' + 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 AssertionError(invalid_email_error) # 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" + if not email.endswith('utoronto.ca'): + logger.error(not_uoft_email_error) + raise AssertionError(not_uoft_email_error) 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 +138,18 @@ 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' + if len(nickname) > 8: + logger.error(nickname_too_long) + raise AssertionError(nickname_too_long) + 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 +157,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 +166,7 @@ class VNCCredentials(db.Model): # db.drop_all() db.engine.execute("CREATE SCHEMA IF NOT EXISTS ictrl;") db.create_all() + logger.info("Database initialization is done.") def login(self, username, password): username = username.lower() @@ -169,7 +197,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("Removed user session: %s", userid) return True @@ -188,6 +217,8 @@ def query(self): "username": session.username } + logger.info("Query user sessions successful, all user sessions:\n%s", json.dumps(_profile)) + return _profile def add_user(self, username, password, email): @@ -236,6 +267,8 @@ def activate_user(self, userid, code): user.activation_type = ActivationType.NORMAL_USER self.save_profile() + logger.info("Successfully activated user with userid=%s", userid) + return True return False @@ -249,6 +282,7 @@ def get_user(self): if user is None: abort(403, 'Cannot find any matching record') + logger.info("Successfully retrieved user with userid=%s", userid) return user def add_session(self, host, username, conn=None): @@ -273,6 +307,8 @@ def add_session(self, host, username, conn=None): session.private_key = f.encrypt(clear_private_key).decode('ascii') self.save_profile() + + 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: @@ -295,6 +331,8 @@ def delete_session(self, session_id): self.db.session.delete(session) self.save_profile() + logger.info("Successfully deleted session, session_id=%s", session_id) + return True, '' def change_host(self, session_id, new_host): @@ -305,14 +343,18 @@ 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) + 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("Cannot retrieve session info: session_id=%s", session_id) return None, None, None, None, None f = Fernet(flask_session['session_crypt_key']) @@ -329,6 +371,8 @@ def set_session_nickname(self, session_id, nickname): session.nickname = nickname self.save_profile() + logger.info("Successfully set session nickname=%s for session %s", nickname, session_id) + return True, '' def set_session_vnc_credentials(self, session_id, credentials): @@ -340,6 +384,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("Successfully deleted vnc credentials for session %s", session_id) else: # it is an add / update request json_str = json.dumps(credentials) @@ -352,12 +397,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("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("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' @@ -389,4 +436,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("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 e7a24c9..7422134 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,6 +38,8 @@ "sessions": {}, } +logger = logging.getLogger(__name__) + class LocalProfile(Profile): def login(self, username, password): @@ -58,24 +61,27 @@ def send_activation_email(self, username): def __init__(self): self._profile = copy.deepcopy(_EMPTY_USER_PROFILE) try: + logger.debug("Attempting to open file: %s", 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.exception('LocalProfile: Error loading profile: %s', e) + logger.warning("Unable to load the user profile. Using the default profile instead.") - def query(self): + def query(self) -> dict[str, object]: + 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 @@ -88,33 +94,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("Failed to save RSA SSH private key in %s", this_private_key_path) return status, reason self.save_profile() + 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('Cannot delete session %s, session does not exist', session_id) 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.exception('No valid SSH key found for deletion') self._profile['sessions'].pop(session_id) self.save_profile() + logger.info("Successfully deleted session %s", 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("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("Successfully changed host for session %s to new host %s", session_id, new_host) + return True, '' def save_profile(self): @@ -126,8 +140,9 @@ 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[object, object, object, None, object]: if session_id not in self._profile['sessions']: + 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'] @@ -138,58 +153,71 @@ def get_session_info(self, session_id): else: nickname = None + 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): + def set_session_nickname(self, session_id, nickname) -> tuple[bool, str]: if session_id not in self._profile['sessions']: + 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.error("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("Successfully deleted nickname from session %s", session_id) else: # it is an add / update request self._profile['sessions'][session_id]['nickname'] = nickname + logger.info("Successfully added/updated nickname for session %s", session_id) self.save_profile() 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("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("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("Successfully added/updated vnc credentials for session %s", session_id) self.save_profile() return True, '' - def get_session_vnc_credentials(self, session_id): + def get_session_vnc_credentials(self, session_id) -> tuple[bool, object]: if session_id not in self._profile['sessions']: + logger.error("Cannot retrieve session %s, session does not exist", session_id) return False, f'failed: session {session_id} does not exist' + 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')) else: return True, '' - def get_user(self): + def get_user(self) -> object: class DummyUser: id = 0 dummy_user = DummyUser() + + logger.debug("Returning user: %s", dummy_user) return dummy_user diff --git a/application/__init__.py b/application/__init__.py index 160468a..a8df7ff 100644 --- a/application/__init__.py +++ b/application/__init__.py @@ -34,7 +34,11 @@ print("Logging setup failed with exception = ", ex) logger = logging.getLogger(__name__) -logger.warning(f"Logging is set up with config={config}") +#Setting the message to warning in case logging set up from dictConfig was not successful +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 @@ -73,7 +77,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..cb78236 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('Created directory, path = %s', path) # setup profile path @@ -33,6 +38,7 @@ def makedir_if_not_exists(path): elif platform.system() == "Darwin" or 'Linux': PROFILE_PATH = os.path.join(os.path.expanduser("~"), ".ictrl") else: + logger.error("Operating System: %s not supported", platform.system()) raise SystemError(f"Operating System: {platform.system()} not supported") makedir_if_not_exists(PROFILE_PATH) diff --git a/application/utils.py b/application/utils.py index ea5f53a..a577422 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,14 +26,23 @@ from email.mime.text import MIMEText +logger = logging.getLogger(__name__) + + def int_to_bytes(num): return 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)) - return sock.getsockname()[1] + socket_info = sock.getsockname() + logger.info("Socket binded to address %s at port %s", socket_info[0], socket_info[1]) + return socket_info[1] def send_email(to_email, subject, body): @@ -53,6 +63,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('Successfully sent email from %s to %s', sender_email, to_email) + server_ssl.close() @@ -77,6 +90,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.warning('Failed to validate password, reason: %s', reason) return False, reason else: return True, None @@ -91,6 +105,8 @@ def get_headers_dict_from_str(headers_str): header_name, header_value = line.split(': ', 1) headers[header_name] = header_value + logger.debug('Extracted HTTP headers, headers = %s', headers) + return headers