From 49038f125aaadc3967a8eec251a4ea69ec5a8869 Mon Sep 17 00:00:00 2001 From: "Jose M. Guisado" Date: Tue, 1 Aug 2023 14:00:32 +0200 Subject: 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) --- src/live/ogOperations.py | 17 ++++++++++------- src/utils/tiptorrent.py | 7 +++++-- 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) -- cgit v1.2.3-18-g5258