Fix logging for msui and mscolab

docs/samples/automation/retriever.py

@@ -118,7 +118,7 @@ def main():
        and, for hsec only, the elevation to plot (if necessary).
     """)
     parser.add_argument("-v", "--version", help="show version", action="store_true", default=False)
-    parser.add_argument("--debug", help="show debugging log messages on console", action="store_true", default=False)
+    parser.add_argument("--loglevel", help="set logging level", dest="loglevel", default=int(logging.INFO))
     parser.add_argument("--logfile", help="Specify logfile location. Set to empty string to disable.", action="store",
                         default=os.path.join(mslib.msui.constants.MSUI_CONFIG_PATH, "msui.log"))
     args = parser.parse_args()
@@ -131,7 +131,7 @@ def main():
         print("Version:", mslib.__version__)
         sys.exit()
 
-    mslib.utils.setup_logging(args)
+    mslib.utils.setup_logging(levelno=args.loglevel, logfile=args.logfile)
     read_config_file(path=mslib.msui.constants.MSUI_SETTINGS)
     config = config_loader()
     num_interpolation_points = config["num_interpolation_points"]

mslib/mscolab/app/__init__.py

@@ -35,11 +35,11 @@
 from flask import Flask, url_for
 from mslib.mscolab.conf import mscolab_settings
 from flask_sqlalchemy import SQLAlchemy
-from mslib.utils import prefix_route, release_info
+from mslib.utils import prefix_route, release_info, LOGGER
 
 message, update = release_info.check_for_new_release()
 if update:
-    logging.warning(message)
+    LOGGER.warning(message)
 
 
 DOCS_SERVER_PATH = os.path.dirname(os.path.abspath(mslib.__file__))

mslib/mscolab/conf.py

@@ -34,6 +34,7 @@
 from saml2.client import Saml2Client
 from saml2.config import SPConfig
 from urllib.parse import urlparse
+from mslib.utils import LOGGER
 
 
 class default_mscolab_settings:
@@ -142,16 +143,16 @@ class default_mscolab_settings:
 
 try:
     import mscolab_settings as user_settings
-    logging.info("Using user defined settings")
+    LOGGER.info("Using user defined settings")
     mscolab_settings.__dict__.update(user_settings.__dict__)
 except ImportError as ex:
-    logging.warning(u"Couldn't import mscolab_settings (ImportError:'%s'), using dummy config.", ex)
+    LOGGER.warning(u"Couldn't import mscolab_settings (ImportError:'%s'), using dummy config.", ex)
 
 try:
     from setup_saml2_backend import setup_saml2_backend
-    logging.info("Using user defined saml2 settings")
+    LOGGER.info("Using user defined saml2 settings")
 except ImportError as ex:
-    logging.warning(u"Couldn't import setup_saml2_backend (ImportError:'%s'), using dummy config.", ex)
+    LOGGER.warning(u"Couldn't import setup_saml2_backend (ImportError:'%s'), using dummy config.", ex)
 
     class setup_saml2_backend:
         # idp settings

mslib/mscolab/file_manager.py

@@ -39,6 +39,7 @@
 from mslib.utils.verify_waypoint_data import verify_waypoint_data
 from mslib.mscolab.models import db, Operation, Permission, User, Change, Message
 from mslib.mscolab.conf import mscolab_settings
+from mslib.utils import LOGGER
 
 
 class FileManager:
@@ -74,7 +75,7 @@ def create_operation(self, path, description, user, last_used=None, content=None
             return False
         # set codes on these later
         if path.find("/") != -1 or path.find("\\") != -1 or (" " in path):
-            logging.debug("malicious request: %s", user)
+            LOGGER.debug("malicious request: %s", user)
             return False
         proj_available = Operation.query.filter_by(path=path).first()
         if proj_available is not None:
@@ -269,7 +270,7 @@ def delete_user_profile_image(self, image_to_be_deleted):
         with fs.open_fs(upload_folder) as profile_fs:
             if profile_fs.exists(image_to_be_deleted):
                 profile_fs.remove(image_to_be_deleted)
-                logging.debug(f"Successfully deleted image: {image_to_be_deleted}")
+                LOGGER.debug(f"Successfully deleted image: {image_to_be_deleted}")
 
     def upload_file(self, file, subfolder=None, identifier=None, include_prefix=False):
         """
@@ -306,7 +307,7 @@ def upload_file(self, file, subfolder=None, identifier=None, include_prefix=Fals
             else:
                 static_file_path = fs.path.relativefrom(upload_folder, fs.path.join(subfolder_path, file_name))
 
-            logging.debug(f'Relative Path: {static_file_path}')
+            LOGGER.debug(f'Relative Path: {static_file_path}')
             return static_file_path
 
     def save_user_profile_image(self, user_id, image_file):
@@ -337,7 +338,7 @@ def update_operation(self, op_id, attribute, value, user):
         operation = Operation.query.filter_by(id=op_id).first()
         if attribute == "path":
             if value.find("/") != -1 or value.find("\\") != -1 or (" " in value):
-                logging.debug("malicious request: %s", user)
+                LOGGER.debug("malicious request: %s", user)
                 return False
             with fs.open_fs(self.data_dir) as data:
                 if data.exists(value):
@@ -549,7 +550,7 @@ def undo_changes(self, ch_id, user):
                 db.session.commit()
                 return True
             except Exception as ex:
-                logging.debug(ex)
+                LOGGER.debug(ex)
                 return False
 
     def fetch_users_without_permission(self, op_id, u_id):

mslib/mscolab/models.py

@@ -34,7 +34,7 @@
 
 from mslib.mscolab.app import db
 from mslib.mscolab.message_type import MessageType
-
+from mslib.utils import LOGGER
 
 class AwareDateTime(sqlalchemy.types.TypeDecorator):
     impl = sqlalchemy.types.DateTime
@@ -116,7 +116,7 @@ def verify_auth_token(token):
                 algorithms=["HS256"]
             )
         except Exception as e:
-            logging.debug("Bad Token %s", str(e))
+            LOGGER.debug("Bad Token %s", str(e))
             return None
 
         user = User.query.filter_by(id=data.get('id')).first()

mslib/mscolab/mscolab.py

@@ -44,17 +44,17 @@
     add_all_users_to_all_operations, delete_user
 from mslib.mscolab.server import APP
 from mslib.mscolab.utils import create_files
-from mslib.utils import setup_logging
+from mslib.utils import setup_logging, LOGGER
 
 
 def handle_start(args=None):
     from mslib.mscolab.server import APP, sockio, cm, fm, start_server
     if args is not None:
-        setup_logging(levelno = args.loglevel, logfile= args.logfile)
-    logging.info("MSS Version: %s", __version__)
-    logging.info("Python Version: %s", sys.version)
-    logging.info("Platform: %s (%s)", platform.platform(), platform.architecture())
-    logging.info("Launching MSColab Server")
+        setup_logging(levelno=args.loglevel, logfile=args.logfile)
+    LOGGER.info("MSS Version: %s", __version__)
+    LOGGER.info("Python Version: %s", sys.version)
+    LOGGER.info("Platform: %s (%s)", platform.platform(), platform.architecture())
+    LOGGER.info("Launching MSColab Server")
     start_server(APP, sockio, cm, fm)
 
 
@@ -108,7 +108,7 @@ def handle_mscolab_certificate_init():
                "/CN=localhost", "-out", os.path.join(mscolab_settings.SSO_DIR,
                                                      "crt_mscolab.crt")]
         subprocess.run(cmd, check=True)
-        logging.info("generated CRTs for the mscolab server.")
+        LOGGER.info("generated CRTs for the mscolab server.")
         return True
     except subprocess.CalledProcessError as error:
         print(f"Error while generating CRTs for the mscolab server: {error}")
@@ -124,7 +124,7 @@ def handle_local_idp_certificate_init():
                "-nodes", "-x509", "-days", "365", "-batch", "-subj",
                "/CN=localhost", "-out", os.path.join(mscolab_settings.SSO_DIR, "crt_local_idp.crt")]
         subprocess.run(cmd, check=True)
-        logging.info("generated CRTs for the local identity provider")
+        LOGGER.info("generated CRTs for the local identity provider")
         return True
     except subprocess.CalledProcessError as error:
         print(f"Error while generated CRTs for the local identity provider: {error}")
@@ -282,7 +282,7 @@ def handle_mscolab_metadata_init(repo_exists):
                     "-o", os.path.join(mscolab_settings.SSO_DIR, "metadata_sp.xml")]
         subprocess.run(cmd_curl, check=True)
         process.terminate()
-        logging.info('mscolab metadata file generated succesfully')
+        LOGGER.info('mscolab metadata file generated succesfully')
         return True
 
     except subprocess.CalledProcessError as error:
@@ -309,7 +309,7 @@ def handle_local_idp_metadata_init(repo_exists):
         with open(os.path.join(mscolab_settings.SSO_DIR, "idp.xml"),
                   "w", encoding="utf-8") as output_file:
             subprocess.run(cmd, stdout=output_file, check=True)
-        logging.info("idp metadata file generated successfully")
+        LOGGER.info("idp metadata file generated successfully")
         return True
     except subprocess.CalledProcessError as error:
         # Delete the idp.xml file when the subprocess fails

mslib/mscolab/seed.py

@@ -32,6 +32,7 @@
 from mslib.mscolab.conf import mscolab_settings
 from mslib.mscolab.models import User, db, Permission, Operation
 from mslib.mscolab.server import APP as app
+from mslib.utils import LOGGER
 
 
 # Todo: refactor move to mscolab.utils
@@ -88,7 +89,7 @@ def add_all_users_default_operation(path='TEMPLATE', description="Operation to k
             return True
         except IntegrityError as err:
             db.session.rollback()
-            logging.debug("Error writing to db: %s", err)
+            LOGGER.debug("Error writing to db: %s", err)
         db.session.close()
 
 
@@ -98,7 +99,7 @@ def delete_user(email):
     with app.app_context():
         user = User.query.filter_by(emailid=str(email)).first()
         if user:
-            logging.info("User: %s deleted from db", email)
+            LOGGER.info("User: %s deleted from db", email)
             db.session.delete(user)
             db.session.commit()
             db.session.close()
@@ -122,10 +123,10 @@ def add_user(email, username, password):
             db.session.add(db_user)
             db.session.commit()
             db.session.close()
-            logging.info("Userdata: %s %s %s", email, username, password)
+            LOGGER.info("Userdata: %s %s %s", email, username, password)
             return True
         else:
-            logging.info("%s already in db", user_name_exists)
+            LOGGER.info("%s already in db", user_name_exists)
     return False
 
 
@@ -194,7 +195,7 @@ def add_user_to_operation(path=None, access_level='admin', emailid=None):
                     return True
                 except IntegrityError as err:
                     db.session.rollback()
-                    logging.debug("Error writing to db: %s", err)
+                    LOGGER.debug("Error writing to db: %s", err)
                 db.session.close()
     return False
 

mslib/mscolab/server.py

@@ -51,7 +51,7 @@
 from mslib.mscolab.models import Change, MessageType, User
 from mslib.mscolab.sockets_manager import _setup_managers
 from mslib.mscolab.utils import create_files, get_message_dict
-from mslib.utils import conditional_decorator
+from mslib.utils import conditional_decorator, LOGGER
 from mslib.index import create_app
 from mslib.mscolab.forms import ResetRequestForm, ResetPasswordForm
 from mslib.mscolab import migrations
@@ -81,7 +81,7 @@ def _handle_db_upgrade():
     )
     # If a database connection to migrate from is set and the target database is empty, then migrate the existing data
     if is_empty_database and mscolab_settings.SQLALCHEMY_DB_URI_TO_MIGRATE_FROM is not None:
-        logging.info("The target database is empty and a database to migrate from is set, starting the data migration")
+        LOGGER.info("The target database is empty and a database to migrate from is set, starting the data migration")
         source_engine = sqlalchemy.create_engine(mscolab_settings.SQLALCHEMY_DB_URI_TO_MIGRATE_FROM)
         source_metadata = sqlalchemy.MetaData()
         source_metadata.reflect(bind=source_engine)
@@ -101,10 +101,10 @@ def _handle_db_upgrade():
                 if table.name == "alembic_version":
                     # Do not migrate the alembic_version table!
                     continue
-                logging.debug("Copying table %s", table.name)
+                LOGGER.debug("Copying table %s", table.name)
                 stmt = target_metadata.tables[table.name].insert()
                 for row in src_connection.execute(table.select()):
-                    logging.debug("Copying row %s", row)
+                    LOGGER.debug("Copying row %s", row)
                     row = tuple(
                         r.replace(tzinfo=datetime.timezone.utc) if isinstance(r, datetime.datetime) else r for r in row
                     )
@@ -113,7 +113,7 @@ def _handle_db_upgrade():
             if target_engine.name == "postgresql":
                 # Fix the databases auto-increment sequences, if it is a PostgreSQL database
                 # For reference, see: https://wiki.postgresql.org/wiki/Fixing_Sequences
-                logging.info("Using a PostgreSQL database, will fix up sequences")
+                LOGGER.info("Using a PostgreSQL database, will fix up sequences")
                 cur = target_connection.execute(sqlalchemy.text(r"""
 SELECT
     'SELECT SETVAL(' ||
@@ -138,12 +138,12 @@ def _handle_db_upgrade():
                 for stmt, in cur.all():
                     target_connection.execute(sqlalchemy.text(stmt))
                 target_connection.commit()
-        logging.info("Data migration finished")
+        LOGGER.info("Data migration finished")
 
     # Upgrade to the latest database revision
     flask_migrate.upgrade(directory=migrations.__path__[0])
 
-    logging.info("Database initialised successfully!")
+    LOGGER.info("Database initialised successfully!")
 
 
 APP = create_app(__name__, imprint=mscolab_settings.IMPRINT, gdpr=mscolab_settings.GDPR)
@@ -157,7 +157,7 @@ def _handle_db_upgrade():
 try:
     from mscolab_auth import mscolab_auth
 except ImportError as ex:
-    logging.warning("Couldn't import mscolab_auth (ImportError:'{%s), creating dummy config.", ex)
+    LOGGER.warning("Couldn't import mscolab_auth (ImportError:'{%s), creating dummy config.", ex)
 
     class mscolab_auth:
         allowed_users = [("mscolab", "add_md5_digest_of_PASSWORD_here"),
@@ -166,7 +166,7 @@ class mscolab_auth:
 
 # setup http auth
 if mscolab_settings.__dict__.get('enable_basic_http_authentication', False):
-    logging.debug("Enabling basic HTTP authentication. Username and "
+    LOGGER.debug("Enabling basic HTTP authentication. Username and "
                   "password required to access the service.")
     import hashlib
 
@@ -196,9 +196,9 @@ def send_email(to, subject, template):
         try:
             mail.send(msg)
         except IOError:
-            logging.error("Can't send email to %s", to)
+            LOGGER.error("Can't send email to %s", to)
     else:
-        logging.debug("setup user verification by email")
+        LOGGER.debug("setup user verification by email")
 
 
 def generate_confirmation_token(email):
@@ -235,7 +235,7 @@ def check_login(emailid, password):
     try:
         user = User.query.filter_by(emailid=str(emailid)).first()
     except sqlalchemy.exc.OperationalError as ex:
-        logging.debug("Problem in the database (%ex), likely version client different", ex)
+        LOGGER.debug("Problem in the database (%ex), likely version client different", ex)
         return False
     if user is not None:
         if mscolab_settings.MAIL_ENABLED:
@@ -274,7 +274,7 @@ def wrapper(*args, **kwargs):
         try:
             user = User.verify_auth_token(request.args.get('token', request.form.get('token', False)))
         except TypeError:
-            logging.debug("no token in request form")
+            LOGGER.debug("no token in request form")
             abort(404)
         if not user:
             return "False"
@@ -379,7 +379,7 @@ def get_auth_token():
                 'token': token,
                 'user': {'username': user.username, 'id': user.id}})
     else:
-        logging.debug("Unauthorized user: %s", emailid)
+        LOGGER.debug("Unauthorized user: %s", emailid)
         return "False"
 
 
@@ -870,7 +870,7 @@ def reset_request():
                 return render_template('user/status.html')
         return render_template('user/reset_request.html', form=form)
     else:
-        logging.warning("To send emails, the value of `MAIL_ENABLED` in `conf.py` should be set to True.")
+        LOGGER.warning("To send emails, the value of `MAIL_ENABLED` in `conf.py` should be set to True.")
         return render_template('errors/403.html'), 403
 
 
@@ -975,7 +975,7 @@ def acs_post_handler():
                 APP.add_url_rule(f'/{assertion_consumer_endpoint}/', assertion_consumer_endpoint,
                                  create_acs_post_handler(idp_config), methods=['POST'])
         except (NameError, AttributeError, KeyError) as ex:
-            logging.warning("USE_SAML2 is %s, Failure is: %s", mscolab_settings.USE_SAML2, ex)
+            LOGGER.warning("USE_SAML2 is %s, Failure is: %s", mscolab_settings.USE_SAML2, ex)
 
     @APP.route('/idp_login_auth/', methods=['POST'])
     def idp_login_auth():