From ed81efcfa2b3249230818a14b81fe238910dedbb Mon Sep 17 00:00:00 2001 From: mickael e Date: Wed, 4 Dec 2019 10:45:17 -0500 Subject: [PATCH] Use logger instead of logging Logging works, but does not provide the class/method/line where the logging was invoked. Logger was used inconsistently accross the codebase. --- securedrop_export/entrypoint.py | 6 ++-- securedrop_export/export.py | 61 +++++++++++++++++---------------- securedrop_export/main.py | 22 ++++++------ 3 files changed, 47 insertions(+), 42 deletions(-) diff --git a/securedrop_export/entrypoint.py b/securedrop_export/entrypoint.py index f2d837202..ed1d69bb1 100755 --- a/securedrop_export/entrypoint.py +++ b/securedrop_export/entrypoint.py @@ -11,6 +11,8 @@ CONFIG_PATH = "/etc/sd-export-config.json" DEFAULT_HOME = os.path.join(os.path.expanduser("~"), ".securedrop_export") +logger = logging.getLogger(__name__) + def configure_logging(): """ @@ -44,13 +46,13 @@ def start(): msg = "ERROR_LOGGING" export.SDExport.exit_gracefully(msg) - logging.info('Starting SecureDrop Export {}'.format(__version__)) + logger.info('Starting SecureDrop Export {}'.format(__version__)) my_sub = export.SDExport(sys.argv[1], CONFIG_PATH) try: # Halt immediately if target file is absent if not os.path.exists(my_sub.archive): - logging.info('Archive is not found {}.'.format(my_sub.archive)) + logger.info('Archive is not found {}.'.format(my_sub.archive)) msg = "ERROR_FILE_NOT_FOUND" my_sub.exit_gracefully(msg) main.__main__(my_sub) diff --git a/securedrop_export/export.py b/securedrop_export/export.py index c2f7b92eb..00c4a83be 100755 --- a/securedrop_export/export.py +++ b/securedrop_export/export.py @@ -82,27 +82,27 @@ def __init__(self, archive_path): try: with open(self.metadata_path) as f: - logging.info('Parsing archive metadata') + logger.info('Parsing archive metadata') json_config = json.loads(f.read()) self.export_method = json_config.get("device", None) self.encryption_method = json_config.get("encryption_method", None) self.encryption_key = json_config.get( "encryption_key", None ) - logging.info( + logger.info( 'Exporting to device {} with encryption_method {}'.format( self.export_method, self.encryption_method ) ) except Exception: - logging.error('Metadata parsing failure') + logger.error('Metadata parsing failure') raise def is_valid(self): - logging.info('Validating metadata contents') + logger.info('Validating metadata contents') if self.export_method not in self.SUPPORTED_EXPORT_METHODS: - logging.error( + logger.error( 'Archive metadata: Export method {} is not supported'.format( self.export_method ) @@ -111,7 +111,7 @@ def is_valid(self): if self.export_method == "disk": if self.encryption_method not in self.SUPPORTED_ENCRYPTION_METHODS: - logging.error( + logger.error( 'Archive metadata: Encryption method {} is not supported'.format( self.encryption_method ) @@ -185,7 +185,7 @@ def popup_message(self, msg): def extract_tarball(self): try: - logging.info('Extracting tarball {} into {}'.format(self.archive, self.tmpdir)) + logger.info('Extracting tarball {} into {}'.format(self.archive, self.tmpdir)) with tarfile.open(self.archive) as tar: tar.extractall(self.tmpdir) except Exception: @@ -195,17 +195,20 @@ def check_usb_connected(self, exit=False) -> None: usb_devices = self._get_connected_usbs() if len(usb_devices) == 0: + logger.info('0 USB devices connected') self.exit_gracefully(ExportStatus.USB_NOT_CONNECTED.value) elif len(usb_devices) == 1: + logger.info('1 USB device connected') self.device = usb_devices[0] if exit: self.exit_gracefully(ExportStatus.USB_CONNECTED.value) elif len(usb_devices) > 1: + logger.info('>1 USB devices connected') # Return generic error until freedomofpress/securedrop-export/issues/25 self.exit_gracefully(ExportStatus.ERROR_GENERIC.value) def _get_connected_usbs(self) -> List[str]: - logging.info('Performing usb preflight') + logger.info('Performing usb preflight') # List all block devices attached to VM that are disks and not partitions. try: lsblk = subprocess.Popen(["lsblk", "-o", "NAME,TYPE"], stdout=subprocess.PIPE, @@ -243,7 +246,7 @@ def set_extracted_device_name(self): # we don't support multiple partitions partition_count = device_and_partitions.decode('utf-8').split('\n').count('part') if partition_count > 1: - logging.debug("multiple partitions not supported") + logger.debug("multiple partitions not supported") self.exit_gracefully(ExportStatus.USB_ENCRYPTION_NOT_SUPPORTED.value) # redefine device to /dev/sda if disk is encrypted, /dev/sda1 if partition encrypted @@ -254,9 +257,9 @@ def set_extracted_device_name(self): def check_luks_volume(self): # cryptsetup isLuks returns 0 if the device is a luks volume # subprocess with throw if the device is not luks (rc !=0) - logging.info('Checking if volume is luks-encrypted') + logger.info('Checking if volume is luks-encrypted') self.set_extracted_device_name() - logging.debug("checking if {} is luks encrypted".format(self.device)) + logger.debug("checking if {} is luks encrypted".format(self.device)) self.safe_check_call( command=["sudo", "cryptsetup", "isLuks", self.device], error_message=ExportStatus.USB_ENCRYPTION_NOT_SUPPORTED.value @@ -276,18 +279,18 @@ def unlock_luks_volume(self, encryption_key): # the luks device is not already unlocked if not os.path.exists(os.path.join("/dev/mapper/", self.encrypted_device)): - logging.debug('Unlocking luks volume {}'.format(self.encrypted_device)) + logger.debug('Unlocking luks volume {}'.format(self.encrypted_device)) p = subprocess.Popen( ["sudo", "cryptsetup", "luksOpen", self.device, self.encrypted_device], stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE ) - logging.debug('Passing key') + logger.debug('Passing key') p.communicate(input=str.encode(encryption_key, "utf-8")) rc = p.returncode if rc != 0: - logging.error('Bad phassphrase for {}'.format(self.encrypted_device)) + logger.error('Bad phassphrase for {}'.format(self.encrypted_device)) self.exit_gracefully(ExportStatus.USB_BAD_PASSPHRASE.value) except subprocess.CalledProcessError: self.exit_gracefully(ExportStatus.USB_ENCRYPTION_NOT_SUPPORTED) @@ -301,7 +304,7 @@ def mount_volume(self): ) mapped_device_path = os.path.join("/dev/mapper/", self.encrypted_device) - logging.info('Mounting {}'.format(mapped_device_path)) + logger.info('Mounting {}'.format(mapped_device_path)) self.safe_check_call( command=["sudo", "mount", mapped_device_path, self.mountpoint], error_message=ExportStatus.ERROR_USB_MOUNT.value @@ -319,24 +322,24 @@ def copy_submission(self): target_path = os.path.join(self.mountpoint, self.target_dirname) subprocess.check_call(["mkdir", target_path]) export_data = os.path.join(self.tmpdir, "export_data/") - logging.info('Copying file to {}'.format(self.target_dirname)) + logger.info('Copying file to {}'.format(self.target_dirname)) subprocess.check_call(["cp", "-r", export_data, target_path]) - logging.info('File copied successfully to {}'.format(self.target_dirname)) + logger.info('File copied successfully to {}'.format(self.target_dirname)) self.popup_message("Files exported successfully to disk.") except (subprocess.CalledProcessError, OSError): self.exit_gracefully(ExportStatus.ERROR_USB_WRITE.value) finally: # Finally, we sync the filesystem, unmount the drive and lock the # luks volume, and exit 0 - logging.info('Syncing filesystems') + logger.info('Syncing filesystems') subprocess.check_call(["sync"]) - logging.info('Unmounting drive from {}'.format(self.mountpoint)) + logger.info('Unmounting drive from {}'.format(self.mountpoint)) subprocess.check_call(["sudo", "umount", self.mountpoint]) - logging.info('Locking luks volume {}'.format(self.encrypted_device)) + logger.info('Locking luks volume {}'.format(self.encrypted_device)) subprocess.check_call( ["sudo", "cryptsetup", "luksClose", self.encrypted_device] ) - logging.info('Deleting temporary directory {}'.format(self.tmpdir)) + logger.info('Deleting temporary directory {}'.format(self.tmpdir)) subprocess.check_call(["rm", "-rf", self.tmpdir]) sys.exit(0) @@ -348,17 +351,17 @@ def wait_for_print(self): printer_idle_string = "printer {} is idle".format(self.printer_name) while True: try: - logging.info('Running lpstat waiting for printer {}'.format(self.printer_name)) + logger.info('Running lpstat waiting for printer {}'.format(self.printer_name)) output = subprocess.check_output(["lpstat", "-p", self.printer_name]) if printer_idle_string in output.decode("utf-8"): - logging.info('Print completed') + logger.info('Print completed') return True else: time.sleep(5) except subprocess.CalledProcessError: self.exit_gracefully(ExportStatus.ERROR_PRINT.value) except TimeoutException: - logging.error('Timeout waiting for printer {}'.format(self.printer_name)) + logger.error('Timeout waiting for printer {}'.format(self.printer_name)) self.exit_gracefully(ExportStatus.ERROR_PRINT.value) return True @@ -374,19 +377,19 @@ def get_printer_uri(self): for line in output.split(): if "usb://" in line.decode("utf-8"): printer_uri = line.decode("utf-8") - logging.info('lpinfo usb printer: {}'.format(printer_uri)) + logger.info('lpinfo usb printer: {}'.format(printer_uri)) # verify that the printer is supported, else exit if printer_uri == "": # No usb printer is connected - logging.info('No usb printers connected') + logger.info('No usb printers connected') self.exit_gracefully(ExportStatus.ERROR_PRINTER_NOT_FOUND.value) elif not any(x in printer_uri for x in ("Brother", "LaserJet")): # printer url is a make that is unsupported - logging.info('Printer {} is unsupported'.format(printer_uri)) + logger.info('Printer {} is unsupported'.format(printer_uri)) self.exit_gracefully(ExportStatus.ERROR_PRINTER_NOT_SUPPORTED.value) - logging.info('Printer {} is supported'.format(printer_uri)) + logger.info('Printer {} is supported'.format(printer_uri)) return printer_uri def install_printer_ppd(self, uri): @@ -505,7 +508,7 @@ def print_file(self, file_to_print): ) file_to_print = converted_path - logging.info('Sending file to printer {}:{}'.format(self.printer_name, file_to_print)) + logger.info('Sending file to printer {}:{}'.format(self.printer_name, file_to_print)) self.safe_check_call( command=["xpp", "-P", self.printer_name, file_to_print], error_message=ExportStatus.ERROR_PRINT.value diff --git a/securedrop_export/main.py b/securedrop_export/main.py index 1c7f6dbc7..d3b5a0bef 100755 --- a/securedrop_export/main.py +++ b/securedrop_export/main.py @@ -16,34 +16,34 @@ def __main__(submission): if submission.archive_metadata.is_valid(): if submission.archive_metadata.export_method == "usb-test": - logging.info('Export archive is usb-test') + logger.info('Export archive is usb-test') submission.check_usb_connected(exit=True) elif submission.archive_metadata.export_method == "disk": - logging.info('Export archive is disk') + logger.info('Export archive is disk') # check_usb_connected looks for the drive, sets the drive to use submission.check_usb_connected() - logging.info('Unlocking volume') + logger.info('Unlocking volume') # exports all documents in the archive to luks-encrypted volume submission.unlock_luks_volume(submission.archive_metadata.encryption_key) - logging.info('Mounting volume') + logger.info('Mounting volume') submission.mount_volume() - logging.info('Copying submission to drive') + logger.info('Copying submission to drive') submission.copy_submission() elif submission.archive_metadata.export_method == "disk-test": - logging.info('Export archive is disk-test') + logger.info('Export archive is disk-test') # check_usb_connected looks for the drive, sets the drive to use submission.check_usb_connected() submission.check_luks_volume() elif submission.archive_metadata.export_method == "printer": - logging.info('Export archive is printer') + logger.info('Export archive is printer') # prints all documents in the archive - logging.info('Searching for printer') + logger.info('Searching for printer') printer_uri = submission.get_printer_uri() - logging.info('Installing printer drivers') + logger.info('Installing printer drivers') printer_ppd = submission.install_printer_ppd(printer_uri) - logging.info('Setting up printer') + logger.info('Setting up printer') submission.setup_printer(printer_uri, printer_ppd) - logging.info('Printing files') + logger.info('Printing files') submission.print_all_files() elif submission.archive_metadata.export_method == "printer-test": # Prints a test page to ensure the printer is functional