From 2dd13d640d585231a5837a4640ecc18d1fbd79a4 Mon Sep 17 00:00:00 2001 From: Nuovaxu Date: Sat, 10 Aug 2024 00:51:26 -0400 Subject: [PATCH 1/2] add routes logging message --- application/routes/audio.py | 9 +++++++-- application/routes/common.py | 20 +++++++++++++++---- application/routes/sftp.py | 37 ++++++++++++++++++++++++++++-------- application/routes/term.py | 13 +++++++++++-- application/routes/user.py | 21 ++++++++++++++++---- application/routes/vnc.py | 22 +++++++++++++++------ 6 files changed, 96 insertions(+), 26 deletions(-) diff --git a/application/routes/audio.py b/application/routes/audio.py index b38f7e2a..13c5202e 100644 --- a/application/routes/audio.py +++ b/application/routes/audio.py @@ -35,22 +35,27 @@ from .. import api from ..codes import ConnectionType from ..features.Audio import AUDIO_PORT - +import logging +logger = logging.getLogger(__name__) @api.route('/audio', methods=['POST']) def start_audio(): + #TODO: Request recieved with body + logger.debug("Audio: Received request to start audio with data: {}".format(request.json)) session_id = request.json.get('session_id') audio, reason = create_connection(session_id, ConnectionType.AUDIO) if reason != '': + logger.warning("Audio: Failed to create audio connection: {}".format(reason)) abort(403, description=reason) status, reason = audio.launch_audio() if status is False: + logger.error("Audio: Audio launch failed: {}".format(reason)) abort(403, description=reason) result = { 'port': AUDIO_PORT, 'audio_id': audio.id } - + logger.info("Audio: Audio launched successfully with ID {} on port {}".format(audio.id, AUDIO_PORT)) return json.dumps(result) diff --git a/application/routes/common.py b/application/routes/common.py index b4a83641..02086c9d 100644 --- a/application/routes/common.py +++ b/application/routes/common.py @@ -31,11 +31,14 @@ from ..features.Term import Term from ..features.VNC import VNC from ..utils import int_to_bytes - +import logging +logger = logging.getLogger(__name__) def create_connection(session_id, conn_type): + logger.debug(f"Common: Attempting to create connection: session_id={session_id}, conn_type={conn_type}") host, username, this_private_key_path, this_private_key_str, _ = profiles.get_session_info(session_id) if host is None: + logger.warning(f"Common: Session not found: {session_id}") abort(403, f'Fail: session {session_id} does not exist') if conn_type == ConnectionType.GENERAL: @@ -49,11 +52,13 @@ def create_connection(session_id, conn_type): elif conn_type == ConnectionType.AUDIO: conn = Audio() else: + logger.error(f"Common: Invalid connection type requested: {conn_type}") raise TypeError(f'Invalid type: {conn_type}') status, reason = conn.connect(host, username, key_filename=this_private_key_path, private_key_str=this_private_key_str) if status is False: + logger.error(f"Common: Connection failed: {reason}") if reason.startswith('[Errno 60]') \ or reason.startswith('[Errno 64]') \ or reason.startswith('[Errno 51]') \ @@ -71,11 +76,13 @@ def create_connection(session_id, conn_type): @api.route('/profiles') def get_profiles(): + logger.info("Common: Fetching all profiles") return profiles.query() @api.route('/session', methods=['GET', 'POST', 'PATCH', 'DELETE']) def handle_session(): + logger.debug(f"Common: Session operation: {request.method}") if request.method == 'GET': session_id = request.args.get('id') host, username, _, _, nickname = profiles.get_session_info(session_id) @@ -90,16 +97,18 @@ def handle_session(): username = request.json.get('username') # FIXME: password should be optional password = request.json.get("password") - + logger.debug("Common: Creating new session") conn = Connection() status, reason = conn.connect(host, username, password=password) if status is False: + logger.warning(f"Common: Failed to create session: {reason}") abort(403, reason) # FIXME: password should be optional: only pass 'conn' if password is given status, reason = profiles.add_session(host, username, conn) if status is False: + logger.error("Common: Failed to save session info") abort(500, reason) return 'success' @@ -112,10 +121,12 @@ def handle_session(): if nickname is not None: # only update nickname + logger.info(f"Common: Updating nickname for session {session_id}") status, reason = profiles.set_session_nickname(session_id, nickname) if not status: abort(400, reason) else: + logger.info("Common: Terminating old session") # terminate old sessions with best efforts # noinspection PyBroadException try: @@ -145,7 +156,7 @@ def handle_session(): elif request.method == 'DELETE': session_id = request.args.get('session_id') - + logger.info(f"Common: Deleting session {session_id}") status, reason = profiles.delete_session(session_id) if not status: abort(403, reason) @@ -160,7 +171,7 @@ def exec_blocking(): session_id = request.json.get('session_id') cmd = request.json.get('cmd') large = request.json.get('large', False) - + logger.debug("Common: Executing blocking command") conn, reason = create_connection(session_id, ConnectionType.GENERAL) if reason != '': abort(403, reason) @@ -171,6 +182,7 @@ def exec_blocking(): else: status, _, stdout, stderr = conn.exec_command_blocking(cmd) if status is False: + logger.error("Common: Command execution failed") abort(500, 'exec failed') result = '\n'.join(stdout) + '\n' + '\n'.join(stderr) diff --git a/application/routes/sftp.py b/application/routes/sftp.py index 6495a48d..607f1912 100644 --- a/application/routes/sftp.py +++ b/application/routes/sftp.py @@ -22,7 +22,8 @@ import posixpath from datetime import datetime from pathlib import Path - +import logging +logger = logging.getLogger(__name__) from flask import request, abort, stream_with_context from .common import create_connection @@ -36,18 +37,22 @@ def sftp_ls(session_id): path = request.args.get('path') + logger.debug(f"Sftp: Listing SFTP directory: {path} for session {session_id}") sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': + logger.error(f"Sftp: SFTP connection failed: {reason}") abort(403, description=reason) status, cwd, file_list = sftp.ls(path) if status is False: + logger.error(f"Sftp: Failed to list directory: {cwd}") abort(400, description=cwd) result = { 'cwd': cwd, 'files': file_list } + logger.info(f"Sftp: Directory listed successfully: {cwd}") return json.dumps(result) @@ -55,9 +60,10 @@ def sftp_ls(session_id): def sftp_dl(session_id): cwd = request.args.get('cwd') args_files = request.args.get('files') - + logger.debug(f"Sftp: Downloading files: {args_files} from {cwd} for session {session_id}") sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': + logger.error(f"Sftp: SFTP connection failed: {reason}") abort(403, description=reason) files = json.loads(args_files) @@ -75,11 +81,12 @@ def sftp_dl(session_id): dt_str = datetime.now().strftime('_%Y%m%d_%H%M%S') zip_name = posixpath.basename(cwd) + dt_str + '.zip' r.headers.set('Content-Disposition', 'attachment', filename=zip_name) + logger.info(f"Sftp: Sending zip file: {zip_name}") else: r = app.response_class(stream_with_context(sftp.dl_generator(files[0])), mimetype='application/octet-stream') r.headers.set('Content-Disposition', 'attachment', filename=files[0]) r.headers.set('Content-Length', size) - + logger.info(f"Sftp: Sending file: {files[0]}") return r @@ -88,15 +95,17 @@ def sftp_rename(session_id): cwd = request.json.get('cwd') old = request.json.get('old') new = request.json.get('new') - + logger.debug(f"Sftp: Renaming file from {old} to {new} in {cwd} for session {session_id}") sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': + logger.error(f"Sftp: SFTP connection failed: {reason}") abort(403, description=reason) status, reason = sftp.rename(cwd, old, new) if not status: + logger.error(f"Sftp: Rename failed: {reason}") abort(400, reason) - + logger.info("Sftp: Rename successful") return 'success' @@ -105,15 +114,19 @@ def sftp_chmod(session_id): path = request.json.get('path') mode = request.json.get('mode') recursive = request.json.get('recursive') + logger.debug(f"Sftp: Changing file mode for {path} to {mode}, recursive: {recursive} in session {session_id}") sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': + logger.error(f"Sftp: SFTP connection failed: {reason}") abort(403, description=reason) status, reason = sftp.chmod(path, mode, recursive) if not status: + logger.error(f"Sftp: CHMOD failed: {reason}") abort(400, reason) + logger.info("Sftp: CHMOD successful") return 'success' @@ -121,15 +134,18 @@ def sftp_chmod(session_id): def sftp_mkdir(session_id): cwd = request.json.get('cwd') name = request.json.get('name') - + logger.debug(f"Sftp: Creating directory {name} in {cwd} for session {session_id}") sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': + logger.error(f"Sftp: SFTP connection failed: {reason}") abort(403, description=reason) status, reason = sftp.mkdir(cwd, name) if status is False: + logger.error(f"Sftp: Directory creation failed: {reason}") abort(400, description=reason) + logger.info("Sftp: Directory created successfully") return 'success' @@ -139,9 +155,11 @@ def sftp_ul(session_id): # no need to use secure_filename because the user should be responsible for her/his input # when not using the client relative_path = request.headers.get('Path') + logger.debug(f"Sftp: Uploading file {relative_path} to {cwd} for session {session_id}") sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': + logger.error(f"Sftp: SFTP connection failed: {reason}") abort(403, description=reason) p = Path(relative_path) @@ -162,7 +180,7 @@ def sftp_ul(session_id): chunk = request.stream.read(UPLOAD_CHUNK_SIZE) sftp_file.close() - + logger.info(f"Sftp: File uploaded successfully: {request_filename}") return 'success' @@ -170,13 +188,16 @@ def sftp_ul(session_id): def sftp_rm(session_id): cwd = request.json.get('cwd') files = request.json.get('files') - + logger.debug(f"Sftp: Removing files {files} from {cwd} for session {session_id}") sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': + logger.error(f"Sftp: SFTP connection failed: {reason}") abort(403, description=reason) status, reason = sftp.rm(cwd, files) if not status: + logger.error(f"Sftp: File removal failed: {reason}") abort(400, description=reason) + logger.info("Sftp: Files removed successfully") return 'success' diff --git a/application/routes/term.py b/application/routes/term.py index 95c7776e..bf24b1f2 100644 --- a/application/routes/term.py +++ b/application/routes/term.py @@ -27,6 +27,8 @@ from ..codes import ICtrlStep, ConnectionType, ICtrlError from ..features.Term import TERM_CONNECTIONS, TERMINAL_PORT from ..utils import int_to_bytes +import logging +logger = logging.getLogger(__name__) # FIXME: store term_id is cookie-based Flask 'session' @@ -35,23 +37,26 @@ def start_terminal(): session_id = request.json.get('sessionID') load_check = request.json.get('loadCheck', True) - + logger.debug(f"Term: Starting terminal session: {session_id}") def generate(): yield int_to_bytes(ICtrlStep.Term.SSH_AUTH) term, reason = create_connection(session_id, ConnectionType.TERM) if reason != '': + logger.error(f"Term: Terminal connection failed: {reason}") yield reason return yield int_to_bytes(ICtrlStep.Term.CHECK_LOAD) if term.is_uoft() and load_check and term.is_load_high(): + logger.warning(f"Term: Load too high to start terminal session: {session_id}") yield int_to_bytes(ICtrlError.SSH.OVER_LOADED) return yield int_to_bytes(ICtrlStep.Term.LAUNCH_SHELL) status, reason = term.launch_shell() if status is False: + logger.error(f"Term: Failed to launch terminal shell: {reason}") abort(403, description=reason) yield int_to_bytes(ICtrlStep.Term.DONE) @@ -59,6 +64,7 @@ def generate(): 'port': TERMINAL_PORT, 'term_id': term.id } + logger.info(f"Term: Terminal session started successfully: {term.id} on port {TERMINAL_PORT}") yield json.dumps(result) return app.response_class(stream_with_context(generate()), mimetype='application/octet-stream') @@ -68,14 +74,17 @@ def generate(): def resize_terminal(): term_id = request.json.get('term_id') if term_id not in TERM_CONNECTIONS: + logger.error(f"Term: Invalid terminal ID for resize: {term_id}") abort(403, description='invalid term_id') width = request.json.get('w') height = request.json.get('h') - + logger.debug(f"Term: Resizing terminal {term_id}: width {width}, height {height}") term = TERM_CONNECTIONS[term_id] status, reason = term.resize(width, height) if status is False: + logger.error(f"Term: Failed to resize terminal {term_id}: {reason}") abort(403, description=reason) + logger.info(f"Term: Terminal {term_id} resized successfully") return 'success' diff --git a/application/routes/user.py b/application/routes/user.py index 0a72286d..248c162c 100644 --- a/application/routes/user.py +++ b/application/routes/user.py @@ -21,14 +21,15 @@ from flask import request, abort from .. import api, profiles - +import logging +logger = logging.getLogger(__name__) # TODO: review the need to remove the argument readings from the APIs, once we finish debugging @api.route('/userid') def index(): user = profiles.get_user() - + logger.info(f"User: Fetching user ID for user: {user.id}") return f'{user.id}' @@ -39,13 +40,17 @@ def register(): username = request.args['username'] password = request.args['password'] email = request.args['email'] + logger.debug(f"User: Received registration via GET for user: {username}") else: username = request.json['username'] password = request.json['password'] email = request.json['email'] + logger.debug(f"User: Received registration via POST for user: {username}") profiles.add_user(username, password, email) + logger.info(f"User: User registered successfully: {username}") except KeyError as e: + logger.error(f"User: Registration failed, {e} is missing") abort(403, f'{e} is missing') return 'Registration Successful' @@ -57,12 +62,16 @@ def login(): if request.method == 'GET': username = request.args['username'] password = request.args['password'] + logger.debug(f"User: Received login via GET for user: {username}") else: username = request.json['username'] password = request.json['password'] + logger.debug(f"User: Received login via POST for user: {username}") profiles.login(username, password) + logger.info(f"User: User logged in successfully: {username}") except KeyError as e: + logger.error(f"User: Login failed, {e} is missing") abort(403, f'{e} is missing') return 'logged in' @@ -71,7 +80,7 @@ def login(): @api.route('/logout') def logout(): profiles.logout() - + logger.info("User: User logged out successfully") return f'logged out' @@ -80,7 +89,9 @@ def resend(): try: username = request.json['username'] profiles.send_activation_email(username) + logger.info(f"User: Activation email resent to user: {username}") except KeyError as e: + logger.error(f"User: Resend activation failed, {e} is missing") abort(403, f'{e} is missing') return 'sent' @@ -90,10 +101,12 @@ def activate(): try: userid = request.args['userid'] code = request.args['code'] - + logger.debug(f"User: Attempting to activate user: {userid}") if profiles.activate_user(userid, code): + logger.info(f"User: User activated successfully: {userid}") return 'Your account has been activated. ' except KeyError as e: + logger.error(f"User: Activation failed, {e} is missing") abort(403, f'{e} is missing') return 'Failed to activate. ' \ diff --git a/application/routes/vnc.py b/application/routes/vnc.py index 7a6c06fc..38ee096e 100644 --- a/application/routes/vnc.py +++ b/application/routes/vnc.py @@ -19,7 +19,7 @@ # IN THE SOFTWARE. import json -import logging + from flask import request, abort, stream_with_context @@ -27,7 +27,8 @@ from .. import api, app, profiles from ..codes import ICtrlStep, ICtrlError, ConnectionType from ..utils import int_to_bytes - +import application +import logging logger = logging.getLogger(__name__) @@ -36,16 +37,19 @@ def start_vnc(): session_id = request.json.get('sessionID') load_check = request.json.get('loadCheck', True) load_credentials = request.json.get('loadCredentials', True) - + logger.debug(f"Starting VNC session: {session_id} with load check: {load_check} and load credentials: {load_credentials}") + def generate(): yield int_to_bytes(ICtrlStep.VNC.SSH_AUTH) vnc, reason = create_connection(session_id, ConnectionType.VNC) if reason != '': yield reason + logger.error(f"Failed to create VNC connection: {reason}") return yield int_to_bytes(ICtrlStep.VNC.CHECK_LOAD) if vnc.is_uoft() and load_check and vnc.is_load_high(): + logger.warning(f"VNC session load is too high for session: {session_id}") yield int_to_bytes(ICtrlError.SSH.OVER_LOADED) return @@ -67,6 +71,7 @@ def generate(): if vnc_password_status: credentials = {'password': password} elif not use5900: + logger.error("VNC password missing for non-ECF and port 5900 not open") yield int_to_bytes(ICtrlError.VNC.PASSWD_MISSING) return else: @@ -82,11 +87,13 @@ def generate(): status, vnc_port = vnc.launch_vnc() if not status: # TODO: handle the other failures + logger.error("Failed to launch VNC server") yield int_to_bytes(ICtrlError.VNC.QUOTA_EXCEEDED) return yield int_to_bytes(ICtrlStep.VNC.CREATE_TUNNEL) ws_port = vnc.create_tunnel(vnc_port) + logger.info(f"VNC session started successfully on websocket port: {ws_port}") yield int_to_bytes(ICtrlStep.VNC.DONE) result = { @@ -101,6 +108,7 @@ def generate(): @api.route('/vncpasswd', methods=['POST']) def change_vncpasswd(): session_id = request.json.get('session_id') + logger.debug(f"Changing VNC password for session: {session_id}") vnc, reason = create_connection(session_id, ConnectionType.VNC) if reason != '': @@ -113,14 +121,14 @@ def change_vncpasswd(): if not status: logger.error("reset_vnc_password() failed with status=%s", reason) abort(403, description=reason) - + logger.info("VNC password changed successfully") return 'success' @api.route('/vnc_reset', methods=['POST']) def reset_vnc(): session_id = request.json.get('session_id') - + logger.debug(f"Resetting VNC settings for session: {session_id}") vnc, reason = create_connection(session_id, ConnectionType.VNC) if reason != '': abort(403, description=reason) @@ -129,6 +137,7 @@ def reset_vnc(): if status is False: abort(403, description=reason) + logger.info("VNC settings reset successfully") return 'success' @@ -136,9 +145,10 @@ def reset_vnc(): def vnc_credentials(): session_id = request.json.get('session_id') credentials = request.json.get('credentials') - + logger.debug(f"Updating VNC credentials for session: {session_id}") status, reason = profiles.set_session_vnc_credentials(session_id, credentials) if status is False: abort(403, description=reason) + logger.info("VNC credentials updated successfully") return 'success' From 7a5bda92311c0d91278a5ae5176a27873f7c3ff6 Mon Sep 17 00:00:00 2001 From: Nuovaxu Date: Sun, 22 Sep 2024 11:26:07 -0400 Subject: [PATCH 2/2] remove unncessary log messages from exception --- application/routes/user.py | 4 ---- 1 file changed, 4 deletions(-) diff --git a/application/routes/user.py b/application/routes/user.py index 248c162c..baab723d 100644 --- a/application/routes/user.py +++ b/application/routes/user.py @@ -50,7 +50,6 @@ def register(): profiles.add_user(username, password, email) logger.info(f"User: User registered successfully: {username}") except KeyError as e: - logger.error(f"User: Registration failed, {e} is missing") abort(403, f'{e} is missing') return 'Registration Successful' @@ -71,7 +70,6 @@ def login(): profiles.login(username, password) logger.info(f"User: User logged in successfully: {username}") except KeyError as e: - logger.error(f"User: Login failed, {e} is missing") abort(403, f'{e} is missing') return 'logged in' @@ -91,7 +89,6 @@ def resend(): profiles.send_activation_email(username) logger.info(f"User: Activation email resent to user: {username}") except KeyError as e: - logger.error(f"User: Resend activation failed, {e} is missing") abort(403, f'{e} is missing') return 'sent' @@ -106,7 +103,6 @@ def activate(): logger.info(f"User: User activated successfully: {userid}") return 'Your account has been activated. ' except KeyError as e: - logger.error(f"User: Activation failed, {e} is missing") abort(403, f'{e} is missing') return 'Failed to activate. ' \