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.

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