src: improve logging messages

Some users have mistakenly reported tiptorrent problems when the process
takes a long time. Specifically by rebooting or powering off the client
in the middle of the md5sum computation stage, just after the tiptorrent
transfer.

Same problem occurs when image creation command takes a long period of
time.

In order to help the user understand the different stages of commands
such as image creation or image restore using tiptorrent, the following
changes have been made to the current logging solution:

- Add log messages to warn users not to reboot or shut down the client
  during a tiptorrent transfer, and also during the md5sum computation
  stage.

- Add a log message telling the user that the image creation processes
  have started.

- Use logging.exception inside "except:" blocks to print a traceback
  with the log messsage.
  (https://docs.python.org/3/library/logging.html#logging.exception)

2 files changed, 15 insertions, 9 deletions

diff --git a/src/live/ogOperations.py b/src/live/ogOperations.py
index df13816..0998b18 100644
--- a/src/live/ogOperations.py
+++ b/src/live/ogOperations.py
@@ -49,7 +49,7 @@ class OgLiveOperations:
             proc = subprocess.call(["pkill", "-9", "browser"])
             proc = subprocess.Popen(["browser", "-qws", url])
         except:
-            logging.error('Cannot restart browser')
+            logging.exception('Cannot restart browser')
             raise ValueError('Error: cannot restart browser')
 
     def _refresh_payload_disk(self, cxt, part_setup, num_disk):
@@ -137,7 +137,7 @@ class OgLiveOperations:
             r = shutil.copy(src, dst)
             tip_write_csum(image_name)
         except:
-            logging.error('Error copying image to cache')
+            logging.exception('Error copying image to cache')
             raise ValueError(f'Error: Cannot copy image {image_name} to cache')
 
     def _restore_image_unicast(self, repo, name, devpath, cache=False):
@@ -168,6 +168,7 @@ class OgLiveOperations:
 
     def _restore_image(self, image_path, devpath):
         logging.debug(f'Restoring image at {image_path} into {devpath}')
+        logging.debug(f'This process can take some time, please *DO NOT SHUT DOWN OR REBOOT* this client')
         cmd_lzop = shlex.split(f'lzop -dc {image_path}')
         cmd_pc = shlex.split(f'partclone.restore -d0 -C -I -o {devpath}')
         cmd_mbuffer = shlex.split('mbuffer -q -m 40M') if shutil.which('mbuffer') else None
@@ -237,7 +238,7 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
-            logging.error('Exception when running "shell run" subprocess')
+            logging.exception('Exception when running "shell run" subprocess')
             raise ValueError('Error: Incorrect command value')
 
         if ogRest.proc.returncode != 0:
@@ -261,7 +262,7 @@ class OgLiveOperations:
                                executable=OG_SHELL)
             (output, error) = ogRest.proc.communicate()
         except:
-            logging.error('Exception when running session subprocess')
+            logging.exception('Exception when running session subprocess')
             raise ValueError('Error: Incorrect command value')
 
         logging.info('Starting OS at disk %s partition %s', disk, partition)
@@ -298,7 +299,7 @@ class OgLiveOperations:
         try:
             inventory = get_hardware_inventory()
         except ValueError as e:
-            logging.error('Error occurred while running get_hardware_inventory')
+            logging.exception('Error occurred while running get_hardware_inventory')
             raise e
         finally:
             self._restartBrowser(self._url)
@@ -456,10 +457,12 @@ class OgLiveOperations:
             p2 = Popen(cmd2, stdin=p1.stdout)
             p1.stdout.close()
 
+            logging.info(f'Running image creation process, please do not shut down or reboot the client')
+
             try:
                     retdata = p2.communicate()
             except OSError as e:
-                    logging.error('Unexpected error when running partclone and lzop commands')
+                    logging.exception('Unexpected error when running partclone and lzop commands')
             finally:
                     logfile.close()
                     p2.terminate()
@@ -473,7 +476,7 @@ class OgLiveOperations:
             image_info = ogGetImageInfo(image_path)
         except:
             self._restartBrowser(self._url)
-            logging.error('Exception when running "image create" subprocess')
+            logging.exception('Exception when running "image create" subprocess')
             raise ValueError('Error: Incorrect command value')
 
         self._write_md5_file(f'/opt/opengnsys/images/{name}.img')
diff --git a/src/utils/tiptorrent.py b/src/utils/tiptorrent.py
index 12230c0..d46b1c7 100644
--- a/src/utils/tiptorrent.py
+++ b/src/utils/tiptorrent.py
@@ -62,6 +62,7 @@ def tip_write_csum(image_name):
 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')
@@ -78,6 +79,7 @@ def tip_client_get(tip_addr, image_name):
     """
     """
     logging.info(f'Fetching image {image_name} from tiptorrent server at {tip_addr}')
+    logging.info('*DO NOT REBOOT OR POWEROFF* the client during this time')
     cmd = f'tiptorrent-client {tip_addr} {image_name}.img'
     logfile = open('/tmp/command.log', 'wb', 0)
 
@@ -87,7 +89,7 @@ def tip_client_get(tip_addr, image_name):
                                 cwd='/opt/opengnsys/cache/opt/opengnsys/images/')
         proc.communicate()
     except:
-        logging.error('Exception when running tiptorrent client GET subprocess')
+        logging.exception('Exception when running tiptorrent client GET subprocess')
         raise ValueError('Unexpected error running tiptorrent subprocess')
     finally:
         logfile.close()
@@ -96,5 +98,6 @@ def tip_client_get(tip_addr, image_name):
         logging.error(f'Error fetching image {image_name} via tiptorrent')
         raise ValueError('Tiptorrent download failed')
     else:
-        logging.info('tiptorrent transfer completed, writing checksum')
+        logging.info('Calculating checksum...')
+        logging.info('*DO NOT REBOOT OR POWEROFF* the client during this time')
         tip_write_csum(image_name)