diff --git a/application/routes/audio.py b/application/routes/audio.py index b38f7e2..882c756 100644 --- a/application/routes/audio.py +++ b/application/routes/audio.py @@ -35,10 +35,13 @@ 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: %s", request.json) session_id = request.json.get('session_id') audio, reason = create_connection(session_id, ConnectionType.AUDIO) if reason != '': @@ -52,5 +55,5 @@ def start_audio(): 'port': AUDIO_PORT, 'audio_id': audio.id } - + logger.info("Audio: Audio launched successfully with ID %s on port %s", audio.id, AUDIO_PORT) return json.dumps(result) diff --git a/application/routes/common.py b/application/routes/common.py index b4a8364..523af50 100644 --- a/application/routes/common.py +++ b/application/routes/common.py @@ -31,9 +31,11 @@ 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("Common: Attempting to create connection: session_id=%s, conn_type=%s", session_id, conn_type) host, username, this_private_key_path, this_private_key_str, _ = profiles.get_session_info(session_id) if host is None: abort(403, f'Fail: session {session_id} does not exist') @@ -49,11 +51,13 @@ def create_connection(session_id, conn_type): elif conn_type == ConnectionType.AUDIO: conn = Audio() else: + logger.error("Common: Invalid connection type requested: %s", 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("Common: Connection failed: %s", reason) if reason.startswith('[Errno 60]') \ or reason.startswith('[Errno 64]') \ or reason.startswith('[Errno 51]') \ @@ -64,6 +68,7 @@ def create_connection(session_id, conn_type): else: print(reason) # TODO: return the other specific codes + logger.error("Common: Unhandled connection failure reason: %s", reason) reason = int_to_bytes(ICtrlError.SSH.GENERAL) return conn, reason @@ -71,13 +76,16 @@ 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("Common: Session operation: %s", request.method) if request.method == 'GET': session_id = request.args.get('id') + logger.debug("Common: Retrieving session with ID: %s", session_id) host, username, _, _, nickname = profiles.get_session_info(session_id) return json.dumps({ @@ -90,7 +98,7 @@ def handle_session(): username = request.json.get('username') # FIXME: password should be optional password = request.json.get("password") - + logger.debug("Common: Creating new session with host=%s, username=%s", host, username) conn = Connection() status, reason = conn.connect(host, username, password=password) @@ -101,7 +109,7 @@ def handle_session(): status, reason = profiles.add_session(host, username, conn) if status is False: abort(500, reason) - + logger.info("Common: Session created successfully for host=%s", host) return 'success' elif request.method == 'PATCH': @@ -112,10 +120,12 @@ def handle_session(): if nickname is not None: # only update nickname + logger.info("Common: Updating nickname for session %s", session_id) status, reason = profiles.set_session_nickname(session_id, nickname) if not status: abort(400, reason) else: + logger.info("Common: Terminating old session with ID %s", session_id) # terminate old sessions with best efforts # noinspection PyBroadException try: @@ -137,6 +147,7 @@ def handle_session(): host += domain + logger.info("Common: Changing host for session %s to %s", session_id, host) status, reason = profiles.change_host(session_id, host) if not status: abort(403, reason) @@ -145,13 +156,15 @@ def handle_session(): elif request.method == 'DELETE': session_id = request.args.get('session_id') - + logger.info("Common: Deleting session with ID: %s", session_id) status, reason = profiles.delete_session(session_id) if not status: abort(403, reason) + logger.info("Common: Session %s deleted successfully", session_id) return 'success' else: + logger.error("Common: Unsupported HTTP method %s for session endpoint", request.method) abort(405) @@ -160,15 +173,17 @@ 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 for session_id=%s", session_id) conn, reason = create_connection(session_id, ConnectionType.GENERAL) if reason != '': abort(403, reason) result: str if large: + logger.debug("Common: Executing large blocking command") result = conn.exec_command_blocking_large(cmd) else: + logger.debug("Common: Executing standard blocking command") status, _, stdout, stderr = conn.exec_command_blocking(cmd) if status is False: abort(500, 'exec failed') diff --git a/application/routes/sftp.py b/application/routes/sftp.py index 6495a48..8223904 100644 --- a/application/routes/sftp.py +++ b/application/routes/sftp.py @@ -22,20 +22,19 @@ import posixpath from datetime import datetime from pathlib import Path - from flask import request, abort, stream_with_context - from .common import create_connection from .. import api, app from ..codes import ConnectionType - +import logging +logger = logging.getLogger(__name__) UPLOAD_CHUNK_SIZE = 1024 * 1024 - @api.route('/sftp_ls/') def sftp_ls(session_id): path = request.args.get('path') + logger.debug("Sftp: Listing SFTP directory: %s for session %s", path, session_id) sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': abort(403, description=reason) @@ -48,6 +47,7 @@ def sftp_ls(session_id): 'cwd': cwd, 'files': file_list } + logger.info("Sftp: Directory listed successfully: %s", cwd) return json.dumps(result) @@ -55,7 +55,7 @@ def sftp_ls(session_id): def sftp_dl(session_id): cwd = request.args.get('cwd') args_files = request.args.get('files') - + logger.debug("Sftp: Downloading files: %s from %s for session %s", args_files, cwd, session_id) sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': abort(403, description=reason) @@ -75,11 +75,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("Sftp: Sending zip file: %s", 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("Sftp: Sending file: %s", files[0]) return r @@ -88,7 +89,7 @@ def sftp_rename(session_id): cwd = request.json.get('cwd') old = request.json.get('old') new = request.json.get('new') - + logger.debug("Sftp: Renaming file from %s to %s in %s for session %s", old, new, cwd, session_id) sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': abort(403, description=reason) @@ -96,7 +97,7 @@ def sftp_rename(session_id): status, reason = sftp.rename(cwd, old, new) if not status: abort(400, reason) - + logger.info("Sftp: Rename successful from %s to %s", old, new) return 'success' @@ -105,6 +106,7 @@ def sftp_chmod(session_id): path = request.json.get('path') mode = request.json.get('mode') recursive = request.json.get('recursive') + logger.debug("Sftp: Changing file mode for %s to %s, recursive: %s in session %s", path, mode, recursive, session_id) sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': @@ -114,6 +116,7 @@ def sftp_chmod(session_id): if not status: abort(400, reason) + logger.info("Sftp: CHMOD successful for %s", path) return 'success' @@ -121,7 +124,7 @@ def sftp_chmod(session_id): def sftp_mkdir(session_id): cwd = request.json.get('cwd') name = request.json.get('name') - + logger.debug("Sftp: Creating directory %s in %s for session %s", name, cwd, session_id) sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': abort(403, description=reason) @@ -130,6 +133,7 @@ def sftp_mkdir(session_id): if status is False: abort(400, description=reason) + logger.info("Sftp: Directory created successfully: %s", name) return 'success' @@ -139,6 +143,7 @@ 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("Sftp: Uploading file %s to %s for session %s", relative_path, cwd, session_id) sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': @@ -151,6 +156,7 @@ def sftp_ul(session_id): if str(relative_dir_path) != '.': cwd = posixpath.join(cwd, relative_dir_path) # TODO: check: will this ever fail? + logger.debug("Sftp: Creating directories recursively for %s", cwd) sftp.exec_command_blocking(f'mkdir -p "{cwd}"') sftp.sftp.chdir(path=cwd) @@ -162,7 +168,7 @@ def sftp_ul(session_id): chunk = request.stream.read(UPLOAD_CHUNK_SIZE) sftp_file.close() - + logger.info("Sftp: File uploaded successfully: %s", request_filename) return 'success' @@ -170,7 +176,7 @@ def sftp_ul(session_id): def sftp_rm(session_id): cwd = request.json.get('cwd') files = request.json.get('files') - + logger.debug("Sftp: Removing files %s from %s for session %s", files, cwd, session_id) sftp, reason = create_connection(session_id, ConnectionType.SFTP) if reason != '': abort(403, description=reason) @@ -179,4 +185,5 @@ def sftp_rm(session_id): if not status: abort(400, description=reason) + logger.info("Sftp: Files removed successfully from %s", cwd) return 'success' diff --git a/application/routes/term.py b/application/routes/term.py index 95c7776..e869249 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,17 +37,19 @@ def start_terminal(): session_id = request.json.get('sessionID') load_check = request.json.get('loadCheck', True) - + logger.debug("Term: Starting terminal session: %s", session_id) def generate(): yield int_to_bytes(ICtrlStep.Term.SSH_AUTH) term, reason = create_connection(session_id, ConnectionType.TERM) if reason != '': + logger.error("Term: Terminal connection failed: %s", 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("Term: Load too high to start terminal session: %s", session_id) yield int_to_bytes(ICtrlError.SSH.OVER_LOADED) return @@ -59,6 +63,7 @@ def generate(): 'port': TERMINAL_PORT, 'term_id': term.id } + logger.info("Term: Terminal session started successfully: %s on port %s", term.id, TERMINAL_PORT) yield json.dumps(result) return app.response_class(stream_with_context(generate()), mimetype='application/octet-stream') @@ -72,10 +77,11 @@ def resize_terminal(): width = request.json.get('w') height = request.json.get('h') - + logger.debug("Term: Resizing terminal %s: width %s, height %s", term_id, width, height) term = TERM_CONNECTIONS[term_id] status, reason = term.resize(width, height) if status is False: abort(403, description=reason) + logger.info("Term: Terminal %s resized successfully", term_id) return 'success' diff --git a/application/routes/user.py b/application/routes/user.py index 0a72286..0a95ef8 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("User: Fetching user ID for user: %s", user.id) return f'{user.id}' @@ -39,12 +40,15 @@ def register(): username = request.args['username'] password = request.args['password'] email = request.args['email'] + logger.debug("User: Received registration via GET for user: %s", username) else: username = request.json['username'] password = request.json['password'] email = request.json['email'] + logger.debug("User: Received registration via POST for user: %s", username) profiles.add_user(username, password, email) + logger.info("User: User registered successfully: %s", username) except KeyError as e: abort(403, f'{e} is missing') @@ -57,11 +61,14 @@ def login(): if request.method == 'GET': username = request.args['username'] password = request.args['password'] + logger.debug("User: Received login via GET for user: %s", username) else: username = request.json['username'] password = request.json['password'] + logger.debug("User: Received login via POST for user: %s", username) profiles.login(username, password) + logger.info("User: User logged in successfully: %s", username) except KeyError as e: abort(403, f'{e} is missing') @@ -71,7 +78,7 @@ def login(): @api.route('/logout') def logout(): profiles.logout() - + logger.info("User: User logged out successfully") return f'logged out' @@ -80,6 +87,7 @@ def resend(): try: username = request.json['username'] profiles.send_activation_email(username) + logger.info("User: Activation email resent to user: %s", username) except KeyError as e: abort(403, f'{e} is missing') return 'sent' @@ -90,12 +98,14 @@ def activate(): try: userid = request.args['userid'] code = request.args['code'] - + logger.debug("User: Attempting to activate user: %s", userid) if profiles.activate_user(userid, code): + logger.info("User: User activated successfully: %s", userid) return 'Your account has been activated. ' except KeyError as e: abort(403, f'{e} is missing') + logger.warning("User: Failed to activate user. Invalid or expired link for userid: %s", userid) return 'Failed to activate. ' \ 'Your activation link might have been expired or replaced. Please visit ' \ 'https://ictrl.ca ' \ diff --git a/application/routes/vnc.py b/application/routes/vnc.py index 7a6c06f..eaba7d4 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("Starting VNC session: %s with load check: %s and load credentials: %s", session_id, load_check, 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("Failed to create VNC connection: %s", reason) return yield int_to_bytes(ICtrlStep.VNC.CHECK_LOAD) if vnc.is_uoft() and load_check and vnc.is_load_high(): + logger.warning("VNC session load is too high for session: %s", 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,12 +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("VNC session started successfully on websocket port: %s", ws_port) yield int_to_bytes(ICtrlStep.VNC.DONE) result = { 'port': ws_port, @@ -101,26 +107,25 @@ def generate(): @api.route('/vncpasswd', methods=['POST']) def change_vncpasswd(): session_id = request.json.get('session_id') + logger.debug("Changing VNC password for session: %s", session_id) vnc, reason = create_connection(session_id, ConnectionType.VNC) if reason != '': - logger.error("create_connection() failed with status=", status) abort(403, description=reason) passwd = request.json.get('passwd') status, reason = vnc.reset_vnc_password(passwd) if not status: - logger.error("reset_vnc_password() failed with status=%s", reason) abort(403, description=reason) - + logger.info("VNC password changed successfully for session: %s", session_id) return 'success' @api.route('/vnc_reset', methods=['POST']) def reset_vnc(): session_id = request.json.get('session_id') - + logger.debug("Resetting VNC settings for session: %s", session_id) vnc, reason = create_connection(session_id, ConnectionType.VNC) if reason != '': abort(403, description=reason) @@ -129,6 +134,7 @@ def reset_vnc(): if status is False: abort(403, description=reason) + logger.info("VNC settings reset successfully for session: %s", session_id) return 'success' @@ -136,9 +142,10 @@ def reset_vnc(): def vnc_credentials(): session_id = request.json.get('session_id') credentials = request.json.get('credentials') - + logger.debug("Updating VNC credentials for session: %s", 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 for session: %s", session_id) return 'success'