From 2a4ce65a20b41a670b274cb473d46e62b4f3c913 Mon Sep 17 00:00:00 2001 From: Alejandro Sirgo Rica Date: Mon, 18 Mar 2024 14:17:12 +0100 Subject: src: centralize error logging into send_internal_server_error Use only the exception messages as the main resource for error messages. The previous error code had string duplication in the form of: logging.error('msg here') raise Exception('msg here') That approach also has the downside of having log duplication as it had the local logging.err() and a global logging.exception() inside send_internal_server_error capturing the exception message. The actual code only requires raising an exception with a proper error message. Improve exception messages to give more error context. Log every AssertionError as a backtrace. Use the 'raise Exception from e' syntax to modify the a previously raised exception 'e' into an exception with aditional context or different type. This also prevents the message that warns about newer exceptions being launch after an initial exception. --- src/live/ogOperations.py | 59 +++++++++++++++++------------------------------- src/ogRest.py | 6 +++-- src/utils/boot.py | 5 ++-- src/utils/fs.py | 12 ++++------ src/utils/legacy.py | 27 +++++++++++----------- src/utils/tiptorrent.py | 20 ++++++---------- src/utils/uefi.py | 5 ++-- 7 files changed, 53 insertions(+), 81 deletions(-) diff --git a/src/live/ogOperations.py b/src/live/ogOperations.py index acb1a0e..d564ea9 100644 --- a/src/live/ogOperations.py +++ b/src/live/ogOperations.py @@ -51,9 +51,8 @@ class OgLiveOperations: try: proc = subprocess.call(["pkill", "-9", "browser"]) proc = subprocess.Popen(["browser", "-qws", url]) - except: - logging.exception('Cannot restart browser') - raise ValueError('Error: cannot restart browser') + except Exception as e: + raise RuntimeError('Cannot restart browser') from e def _refresh_payload_disk(self, cxt, part_setup, num_disk): part_setup['disk'] = str(num_disk) @@ -120,8 +119,7 @@ class OgLiveOperations: def _write_md5_file(self, path): if not os.path.exists(path): - logging.error('Invalid path in _write_md5_file') - raise ValueError('Invalid image path when computing md5 checksum') + raise ValueError(f'Invalid image path {path} when computing md5 checksum') filename = path + ".full.sum" dig = self._compute_md5(path) try: @@ -145,15 +143,13 @@ class OgLiveOperations: try: r = shutil.copy(src, dst) tip_write_csum(image_name) - except: - logging.exception('Error copying image to cache') - raise ValueError(f'Error: Cannot copy image {image_name} to cache') + except Exception as e: + raise RuntimeError(f'Error copying image {image_name} to cache. Reported: {e}') from e def _restore_image_unicast(self, repo, name, devpath, cache=False): if ogChangeRepo(repo, smb_user=self._smb_user, smb_pass=self._smb_pass) != 0: self._restartBrowser(self._url) - logging.error('ogChangeRepo could not change repository to %s', repo) - raise ValueError(f'Error: Cannot change repository to {repo}') + raise ValueError(f'Cannot change repository to {repo}') logging.debug(f'restore_image_unicast: name => {name}') if cache: image_path = f'/opt/opengnsys/cache/opt/opengnsys/images/{name}.img' @@ -191,8 +187,7 @@ class OgLiveOperations: cmd_pc = shlex.split(f'partclone.restore -d0 -C -I -o {devpath}') if not os.path.exists(image_path): - logging.error('f{image_path} does not exist, exiting.') - raise ValueError(f'Error: Image not found at {image_path}') + raise RuntimeError(f'Image not found at {image_path} during image restore') with open('/tmp/command.log', 'wb', 0) as logfile: proc_lzop = subprocess.Popen(cmd_lzop, @@ -248,9 +243,8 @@ class OgLiveOperations: shell=True, executable=OG_SHELL) (output, error) = ogRest.proc.communicate() - except: - logging.exception('Exception when running "shell run" subprocess') - raise ValueError('Error: Incorrect command value') + except Exception as e: + raise RuntimeError(f'Error when running "shell run" subprocess: {e}') from e if ogRest.proc.returncode != 0: logging.warn('Non zero exit code when running: %s', ' '.join(cmds)) @@ -298,9 +292,8 @@ class OgLiveOperations: try: inventory = get_hardware_inventory() - except ValueError as e: - logging.exception('Error occurred while running get_hardware_inventory') - raise e + except Exception as e: + raise RuntimeError(f'Error while running hardware inventory. {e}') from e finally: self._restartBrowser(self._url) @@ -327,7 +320,6 @@ class OgLiveOperations: elif table_type == 'GPT': cxt.create_disklabel('gpt') else: - logging.info(f'Unsupported partition layout: {table_type}, only MSDOS and GPT are supported') raise ValueError(f'Unsupported partition scheme {table_type}, only MSDOS and GPT are supported') logging.info(f'Setting up partition layout to {table_type}') @@ -422,8 +414,7 @@ class OgLiveOperations: if ogChangeRepo(repo, smb_user=self._smb_user, smb_pass=self._smb_pass) != 0: self._restartBrowser(self._url) - logging.error('ogChangeRepo could not change repository to %s', repo) - raise ValueError(f'Error: Cannot change repository to {repo}') + raise RuntimeError(f'Cannot change image repository to {repo}') if ogRest.terminated: return @@ -439,30 +430,25 @@ class OgLiveOperations: if pa is None: self._restartBrowser(self._url) - logging.error(f'Target partition /dev/{diskname} not found') - raise ValueError(f'Target partition /dev/{diskname} not found') + raise RuntimeError(f'Target partition /dev/{diskname} not found') padev = cxt.partition_to_string(pa, fdisk.FDISK_FIELD_DEVICE) fstype = cxt.partition_to_string(pa, fdisk.FDISK_FIELD_FSTYPE) if not fstype: - logging.error(f'No filesystem detected in {padev}. Aborting image creation.') - raise ValueError('Target partition has no filesystem present') + raise RuntimeError(f'No filesystem detected in {padev}. Aborting image creation') if change_access(user=self._smb_user, pwd=self._smb_pass) == -1: - logging.error('remount of /opt/opengnsys/images has failed') - raise AssertionError('remount of /opt/opengnsys/images has failed') + raise RuntimeError('remount of /opt/opengnsys/images has failed') if os.access(f'/opt/opengnsys/images', os.R_OK | os.W_OK) == False: - logging.error('Cannot access /opt/opengnsys/images in read and write mode, check permissions') - raise ValueError('Cannot access image folder') + raise RuntimeError('Cannot access /opt/opengnsys/images in read and write mode, check permissions') if os.access(f'{image_path}', os.R_OK) == True: logging.info(f'image file {image_path} already exists, updating.') ogCopyEfiBootLoader(disk, partition) if ogReduceFs(disk, partition) == -1: - logging.error(f'Failed to shrink {fstype} filesystem in {padev}') - raise ValueError('Failed to shrink filesystem') + raise ValueError(f'Failed to shrink {fstype} filesystem in {padev}') cmd1 = shlex.split(f'partclone.{fstype} -I -C --clone -s {padev} -O -') cmd2 = shlex.split(f'lzop -1 -fo {image_path}') @@ -482,7 +468,7 @@ class OgLiveOperations: try: retdata = p2.communicate() except OSError as e: - logging.exception('Unexpected error when running partclone and lzop commands') + raise OSError(f'Unexpected error when running partclone and lzop commands: {e}') from e finally: logfile.close() p2.terminate() @@ -494,14 +480,12 @@ class OgLiveOperations: ogExtendFs(disk, partition) if os.access(f'{image_path}', os.R_OK) == False: - logging.error(f'Cannot access partclone image file {image_path}') - raise ValueError('Cannot access image file') + raise RuntimeError(f'Cannot access partclone image file {image_path}') image_info = ogGetImageInfo(image_path) except: self._restartBrowser(self._url) - logging.exception('Exception when running "image create" subprocess') - raise ValueError(f'Error: Cannot create image for {fstype} filesystem in device {padev}') + raise RuntimeError(f'Error: Cannot create image for {fstype} filesystem in device {padev}') try: st = os.stat(image_path) @@ -519,8 +503,7 @@ class OgLiveOperations: image_info.mtime = mtime if self._write_md5_file(f'/opt/opengnsys/images/{name}.img') == -1: - logging.error(f'cannot write {name}.full.sum file') - raise ValueError(f'Error: Cannot write {name}.full.sum file') + raise ValueError(f'Cannot write {name}.full.sum file') self._restartBrowser(self._url) diff --git a/src/ogRest.py b/src/ogRest.py index 7848c3d..47767b6 100644 --- a/src/ogRest.py +++ b/src/ogRest.py @@ -266,8 +266,10 @@ class ogRest(): raise ValueError('Mode not supported.') def send_internal_server_error(self, client, exc=None): - if exc: - logging.exception('Unexpected error') + if isinstance(exc, AssertionError): + logging.exception(exc) + else: + logging.error(exc) response = restResponse(ogResponses.INTERNAL_ERR, seq=client.seq) client.send(response.get()) self.state = ThreadState.IDLE diff --git a/src/utils/boot.py b/src/utils/boot.py index a5ff04b..c9b12ee 100644 --- a/src/utils/boot.py +++ b/src/utils/boot.py @@ -38,9 +38,8 @@ def _boot_bios_linux(disk, part, mountpoint): try: subprocess.run(shlex.split(kexec_cmd), check=True, text=True) subprocess.run(shlex.split(kexec_reboot_cmd), check=True, text=True) - except subprocess.CalledProcessError as e: - logging.error(f'Error processing kexec: {e}') - raise e + except OSError as e: + raise OSError(f'Error processing kexec: {e}') from e def _boot_bios_windows(disk, part, mountpoint): logging.info(f'Booting Windows system') diff --git a/src/utils/fs.py b/src/utils/fs.py index 69b4789..1015754 100644 --- a/src/utils/fs.py +++ b/src/utils/fs.py @@ -150,14 +150,12 @@ def mkfs(fs, disk, partition, label=None): } if fs not in fsdict: - logging.error(f'mkfs fails, unsupported target filesystem {fs}') - raise ValueError(f'Unsupported target filesystem {fs}') + raise ValueError(f'mkfs failed, unsupported target filesystem {fs}') try: partdev = get_partition_device(disk, partition) except ValueError as e: - logging.error(f'mkfs aborted, invalid partition.') - raise e + raise ValueError(f'mkfs aborted: {e}') from e fsdict[fs](partdev, label) @@ -253,13 +251,11 @@ def _reduce_ntfsresize(partdev): data_split = output_data.split(pattern) # If we fail to match pattern in the split then data_split will contain [output_data] if len(data_split) == 1: - logging.error(f'nfsresize: failed to find: "{pattern}"') - raise ValueError(f'nfsresize: failed to find: "{pattern}"') + raise ValueError(f'nfsresize: failed to find: {pattern}') value_str = data_split[1].split(' ')[0] if not value_str.isdigit() or value_str.startswith('-'): - logging.error(f'nfsresize: failed to parse numeric value at "{pattern}"') - raise ValueError(f'nfsresize: failed to parse numeric value at "{pattern}"') + raise ValueError(f'nfsresize: failed to parse numeric value at {pattern}') return int(value_str) try: diff --git a/src/utils/legacy.py b/src/utils/legacy.py index 387f790..d3a0318 100644 --- a/src/utils/legacy.py +++ b/src/utils/legacy.py @@ -209,8 +209,7 @@ def restoreImageCustom(repo_ip, image_name, disk, partition, method): """ """ if not shutil.which('restoreImageCustom'): - logging.error('Invalid restoreImageCustom invocation') - raise ValueError('Error: restoreImageCustom not found') + raise OSError('restoreImageCustom not found') cmd = f'restoreImageCustom {repo_ip} {image_name} {disk} {partition} {method}' with open('/tmp/command.log', 'wb', 0) as logfile: @@ -218,10 +217,10 @@ def restoreImageCustom(repo_ip, image_name, disk, partition, method): proc = subprocess.run(cmd, stdout=logfile, encoding='utf-8', - shell=True) - except: - logging.error('Exception when running restoreImageCustom subprocess') - raise ValueError('Error: Incorrect command value') + shell=True, + check=True) + except OSError as e: + raise OSError(f'Error processing restoreImageCustom: {e}') from e return proc.returncode @@ -237,11 +236,11 @@ def configureOs(disk, partition): proc = subprocess.run(cmd_configure, stdout=PIPE, encoding='utf-8', - shell=True) + shell=True, + check=True) out = proc.stdout - except: - logging.error('Exception when running configureOs subprocess') - raise ValueError('Error: Incorrect command value') + except OSError as e: + raise OSError(f'Error processing configureOsCustom: {e}') from e return out @@ -250,7 +249,7 @@ def ogCopyEfiBootLoader(disk, partition): cmd = f'ogCopyEfiBootLoader {disk} {partition}' try: proc = subprocess.run(cmd, - shell=True) - except: - logging.error('Exception when running ogCopyEfiBootLoader subprocess') - raise ValueError('Subprocess error: ogCopyEfiBootloader') + shell=True, + check=True) + except OSError as e: + raise OSError(f'Error processing ogCopyEfiBootLoader: {e}') from e diff --git a/src/utils/tiptorrent.py b/src/utils/tiptorrent.py index d46b1c7..18c4df7 100644 --- a/src/utils/tiptorrent.py +++ b/src/utils/tiptorrent.py @@ -33,11 +33,9 @@ def tip_fetch_csum(tip_addr, image_name): with urllib.request.urlopen(f'{url}') as resp: r = resp.readline().rstrip().decode('utf-8') except urllib.error.URLError as e: - logging.warning('URL error when fetching checksum: {e.reason}') - raise e + raise urllib.error.URLError(f'URL error when fetching checksum: {e.reason}') from e except urllib.error.HTTPError as e: - logging.warning(f'HTTP Error when fetching checksum: {e.reason}') - raise e + raise urllib.error.URLError(f'HTTP Error when fetching checksum: {e.reason}') from e return r @@ -48,8 +46,7 @@ def tip_write_csum(image_name): image_path = f'/opt/opengnsys/cache/opt/opengnsys/images/{image_name}.img' if not os.path.exists(image_path): - logging.error('Invalid image path') - raise ValueError('Invalid image path for tiptorrent checksum writing') + raise RuntimeError(f'Invalid image path {image_path} for tiptorrent checksum writing') filename = image_path + ".full.sum" csum = _compute_md5(image_path) @@ -65,8 +62,7 @@ def tip_check_csum(tip_addr, image_name): logging.info(f'Verifying checksum for {image_name}.img, please wait...') image_path = f'/opt/opengnsys/cache/opt/opengnsys/images/{image_name}.img' if not os.path.exists(image_path): - logging.error('Invalid image path') - raise ValueError('Invalid image path for tiptorrent image csum comparison') + raise RuntimeError(f'Invalid image path {image_path} for tiptorrent image csum comparison') cache_csum = _compute_md5(image_path) remote_csum = tip_fetch_csum(tip_addr, image_name) @@ -88,15 +84,13 @@ def tip_client_get(tip_addr, image_name): stdout=logfile, cwd='/opt/opengnsys/cache/opt/opengnsys/images/') proc.communicate() - except: - logging.exception('Exception when running tiptorrent client GET subprocess') - raise ValueError('Unexpected error running tiptorrent subprocess') + except OSError as e: + raise OSError('Unexpected error running tiptorrent subprocess: {e}') from e finally: logfile.close() if proc.returncode != 0: - logging.error(f'Error fetching image {image_name} via tiptorrent') - raise ValueError('Tiptorrent download failed') + raise RuntimeError(f'Error fetching image {image_name} via tiptorrent') else: logging.info('Calculating checksum...') logging.info('*DO NOT REBOOT OR POWEROFF* the client during this time') diff --git a/src/utils/uefi.py b/src/utils/uefi.py index 67f1354..e113512 100644 --- a/src/utils/uefi.py +++ b/src/utils/uefi.py @@ -104,6 +104,5 @@ def efibootmgr_create_bootentry(disk, part, loader, label, add_to_bootorder=True logging.info(f'{EFIBOOTMGR_BIN} command creating boot entry: {efibootmgr_cmd}') try: proc = subprocess.run(shlex.split(efibootmgr_cmd), check=True, text=True) - except subprocess.CalledProcessError as e: - logging.error(f'Unexpected error adding boot entry to nvram. UEFI firmware might be buggy?.') - raise e + except OSError as e: + raise OSError(f'Unexpected error adding boot entry to nvram. UEFI firmware might be buggy') from e -- cgit v1.2.3-18-g5258