iCtrl logging setup for files in application.Profile and general python files within the application directory

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,42 +143,56 @@ 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"}
 
             session_id = db.Column(UUID(as_uuid=True), db.ForeignKey('ictrl.session.id'), primary_key=True,
                                    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
 
         # 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,12 +425,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'
@@ -372,10 +447,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 +467,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