Add logging to sd-export

securedrop_export/__init__.py

@@ -0,0 +1 @@
+__version__ = '0.1.1'

securedrop_export/entrypoint.py

@@ -1,18 +1,54 @@
+import logging
 import os
 import shutil
 import sys
 
+from logging.handlers import TimedRotatingFileHandler
+from securedrop_export import __version__
 from securedrop_export import export
 from securedrop_export import main
 
 CONFIG_PATH = "/etc/sd-export-config.json"
+DEFAULT_HOME = os.path.join(os.path.expanduser("~"), ".securedrop_export")
 
+def configure_logging():
+    """
+    All logging related settings are set up by this function.
+    """
+    log_folder = os.path.join(DEFAULT_HOME, 'logs')
+    if not os.path.exists(log_folder):
+        os.makedirs(log_folder)
+
+    log_file = os.path.join(DEFAULT_HOME, 'logs', 'export.log')
+
+    # set logging format
+    log_fmt = ('%(asctime)s - %(name)s:%(lineno)d(%(funcName)s) '
+               '%(levelname)s: %(message)s')
+    formatter = logging.Formatter(log_fmt)
+
+    handler = TimedRotatingFileHandler(log_file)
+    handler.setFormatter(formatter)
+    handler.setLevel(logging.DEBUG)
+
+    # set up primary log
+    log = logging.getLogger()
+    log.setLevel(logging.DEBUG)
+    log.addHandler(handler)
 
 def start():
+    try:
+        configure_logging()
+    except Exception:
+        msg = "ERROR_LOGGING"
+        my_sub.exit_gracefully(msg)
+
+    logging.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))
             msg = "ERROR_FILE_NOT_FOUND"
             my_sub.exit_gracefully(msg)
         main.__main__(my_sub)

securedrop_export/export.py

@@ -2,6 +2,7 @@
 
 import datetime
 import json
+import logging
 import os
 import shutil
 import signal
@@ -19,6 +20,7 @@
 BRLASER_DRIVER = "/usr/share/cups/drv/brlaser.drv"
 BRLASER_PPD = "/usr/share/cups/model/br7030.ppd"
 
+logger = logging.getLogger(__name__)
 
 class Metadata(object):
     """
@@ -40,20 +42,26 @@ def __init__(self, archive_path):
 
         try:
             with open(self.metadata_path) as f:
+                logging.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('Exporting to device {} with encryption_method {}'.format(self.export_method, self.encryption_method))
 
         except Exception:
+            logging.error('Metadata parsing failure')
             raise
 
     def is_valid(self):
+        logging.info('Validating metadata contents')
         if self.export_method not in self.SUPPORTED_EXPORT_METHODS:
+            logging.error('Archive metadata: Export method {} is not supported'.format(self.export_method))
             return False
 
         if self.export_method == "disk":
             if self.encryption_method not in self.SUPPORTED_ENCRYPTION_METHODS:
+                logging.error('Archive metadata: Encryption method {} is not supported'.format(self.encryption_method))
                 return False
         return True
 
@@ -79,11 +87,15 @@ def __init__(self, archive, config_path):
 
         try:
             with open(config_path) as f:
+                logging.info('Retrieving VM configuration')
                 json_config = json.loads(f.read())
                 self.pci_bus_id = json_config.get("pci_bus_id", None)
+                logging.info('pci_bus_id is {}'.format(self.pci_bus_id))
                 if self.pci_bus_id is None:
-                  raise
+                    logging.error('pci_bus_id is not set in VM configuration')
+                    raise
         except Exception:
+            logger.error("error parsing VM configuration.")
             self.exit_gracefully("ERROR_CONFIG")
 
     def exit_gracefully(self, msg, e=False):
@@ -95,12 +107,14 @@ def exit_gracefully(self, msg, e=False):
         """
         sys.stderr.write(msg)
         sys.stderr.write("\n")
+        logger.info('Exiting with message: {}'.format(msg))
         if e:
             try:
                 # If the file archive was extracted, delete before returning
                 if os.path.isdir(self.tmpdir):
                     shutil.rmtree(self.tmpdir)
                 e_output = e.output
+                logger.error(e_output)
             except Exception:
                 e_output = "<unknown exception>"
             sys.stderr.write(e_output)
@@ -127,6 +141,7 @@ def popup_message(self, msg):
 
     def extract_tarball(self):
         try:
+            logging.info('Extracting tarball {} into {}'.format(self.archive, self.tmpdir))
             with tarfile.open(self.archive) as tar:
                 tar.extractall(self.tmpdir)
         except Exception:
@@ -137,18 +152,22 @@ def check_usb_connected(self):
 
         # If the USB is not attached via qvm-usb attach, lsusb will return empty string and a
         # return code of 1
+        logging.info('Performing usb preflight')
         try:
-          p = subprocess.check_output(["lsusb", "-s", "{}:".format(self.pci_bus_id)])
+            p = subprocess.check_output(["lsusb", "-s", "{}:".format(self.pci_bus_id)])
+            logging.info("lsusb -s {} : {}".format(self.pci_bus_id, p.decode("utf-8")))
         except subprocess.CalledProcessError:
             msg = "ERROR_USB_CONFIGURATION"
             self.exit_gracefully(msg)
         n_usb = len(p.decode("utf-8").rstrip().split("\n"))
         # If there is one device, it is the root hub.
         if n_usb == 1:
+            logging.info('usb preflight - no external devices connected')
             msg = "USB_NOT_CONNECTED"
             self.exit_gracefully(msg)
         # If there are two devices, it's the root hub and another device (presumably for export)
         elif n_usb == 2:
+            logging.info('usb preflight - external device connected')
             msg = "USB_CONNECTED"
             self.exit_gracefully(msg)
         # Else the result is unexpected
@@ -157,6 +176,7 @@ def check_usb_connected(self):
             self.exit_gracefully(msg)
 
     def check_luks_volume(self):
+        logging.info('Checking if volume is luks-encrypted')
         try:
             # cryptsetup isLuks returns 0 if the device is a luks volume
             # subprocess with throw if the device is not luks (rc !=0)
@@ -169,16 +189,19 @@ def check_luks_volume(self):
 
     def unlock_luks_volume(self, encryption_key):
         # the luks device is not already unlocked
+        logging.info('Unlocking luks volume {}'.format(self.encrypted_device))
         if not os.path.exists(os.path.join("/dev/mapper/", self.encrypted_device)):
             p = subprocess.Popen(
                 ["sudo", "cryptsetup", "luksOpen", self.device, self.encrypted_device],
                 stdin=subprocess.PIPE,
                 stdout=subprocess.PIPE,
                 stderr=subprocess.PIPE,
             )
+            logging.info('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))
                 msg = "USB_BAD_PASSPHRASE"
                 self.exit_gracefully(msg)
 
@@ -187,6 +210,7 @@ def mount_volume(self):
         if not os.path.exists(self.mountpoint):
             subprocess.check_call(["sudo", "mkdir", self.mountpoint])
         try:
+            logging.info('Mounting {} to {}'.format(self.encrypted_device, self.mountpoint))
             subprocess.check_call(
                 [
                     "sudo",
@@ -198,6 +222,8 @@ def mount_volume(self):
             subprocess.check_call(["sudo", "chown", "-R", "user:user", self.mountpoint])
         except subprocess.CalledProcessError:
             # clean up
+            logging.error('Error mounting {} to {}'.format(self.encrypted_device, self.mountpoint))
+            logging.info('Locking luks volume {}'.format(self.encrypted_device))
             subprocess.check_call(
                 ["sudo", "cryptsetup", "luksClose", self.encrypted_device]
             )
@@ -210,19 +236,25 @@ 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))
             subprocess.check_call(["cp", "-r", export_data, target_path])
+            logging.info('File copied successfully to {}'.format(self.target_dirname))
             self.popup_message("Files exported successfully to disk.")
         except (subprocess.CalledProcessError, OSError):
             msg = "ERROR_USB_WRITE"
             self.exit_gracefully(msg)
         finally:
             # Finally, we sync the filesystem, unmount the drive and lock the
             # luks volume, and exit 0
+            logging.info('Syncing filesystems')
             subprocess.check_call(["sync"])
+            logging.info('Unmounting drive from {}'.format(self.mountpoint))
             subprocess.check_call(["sudo", "umount", self.mountpoint])
+            logging.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))
             subprocess.check_call(["rm", "-rf", self.tmpdir])
             sys.exit(0)
 
@@ -234,15 +266,18 @@ 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))
                 output = subprocess.check_output(["lpstat", "-p", self.printer_name])
                 if printer_idle_string in output.decode("utf-8"):
+                    logging.info('Print completed')
                     return True
                 else:
                     time.sleep(5)
             except subprocess.CalledProcessError:
                 msg = "ERROR_PRINT"
                 self.exit_gracefully(msg)
             except TimeoutException:
+                logging.error('Timeout waiting for printer {}'.format(self.printer_name))
                 msg = "ERROR_PRINT"
                 self.exit_gracefully(msg)
         return True
@@ -260,15 +295,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))
 
         # verify that the printer is supported, else exit
         if printer_uri == "":
             # No usb printer is connected
+            logging.info('No usb printers connected')
             self.exit_gracefully("ERROR_PRINTER_NOT_FOUND")
         elif "Brother" in printer_uri:
+            logging.info('Printer {} is supported'.format(printer_uri))
             return printer_uri
         else:
             # printer url is a make that is unsupported
+            logging.info('Printer {} is unsupported'.format(printer_uri))
             self.exit_gracefully("ERROR_PRINTER_NOT_SUPPORTED")
 
     def install_printer_ppd(self, uri):
@@ -352,12 +391,14 @@ def print_file(self, file_to_print):
             # if the file to print is an (open)office document, we need to call unoconf to convert
             # the file to pdf as printer drivers do not immediately support this format out of the box
             if self.is_open_office_file(file_to_print):
+                logging.info('Converting Office document to pdf for printing'.format(self.printer_name))
                 folder = os.path.dirname(file_to_print)
                 converted_filename = file_to_print + ".pdf"
                 converted_path = os.path.join(folder, converted_filename)
                 subprocess.check_call(["unoconv", "-o", converted_path, file_to_print])
                 file_to_print = converted_path
 
+            logging.info('Sending file to printer {}:{}'.format(self.printer_name))
             subprocess.check_call(["xpp", "-P", self.printer_name, file_to_print])
         except subprocess.CalledProcessError:
             msg = "ERROR_PRINT"

securedrop_export/main.py

@@ -1,5 +1,8 @@
+import logging
+
 from securedrop_export import export
 
+logger = logging.getLogger(__name__)
 
 def __main__(submission):
     submission.extract_tarball()
@@ -11,19 +14,30 @@ def __main__(submission):
 
     if submission.archive_metadata.is_valid():
         if submission.archive_metadata.export_method == "usb-test":
+            logging.info('Export archive is usb-test')
             submission.check_usb_connected()
         elif submission.archive_metadata.export_method == "disk":
+            logging.info('Export archive is disk')
+            logging.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')
             submission.mount_volume()
+            logging.info('Copying submission to drive')
             submission.copy_submission()
         elif submission.archive_metadata.export_method == "disk-test":
+            logging.info('Export archive is disk-test')
             submission.check_luks_volume()
         elif submission.archive_metadata.export_method == "printer":
+            logging.info('Export archive is printer')
             # prints all documents in the archive
+            logging.info('Searching for printer')
             printer_uri = submission.get_printer_uri()
+            logging.info('Installing printer drivers')
             printer_ppd = submission.install_printer_ppd(printer_uri)
+            logging.info('Setting up printer')
             submission.setup_printer(printer_uri, printer_ppd)
+            logging.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

update_version.sh

@@ -21,6 +21,8 @@ fi
 if [[ "$OSTYPE" == "darwin"* ]]; then
     # The empty '' after sed -i is required on macOS to indicate no backup file should be saved.
     sed -i '' "s@$(echo "${OLD_VERSION}" | sed 's/\./\\./g')@$NEW_VERSION@g" securedrop_export/VERSION
+    sed -i '' "s@$(echo "${OLD_VERSION}" | sed 's/\./\\./g')@$NEW_VERSION@g" securedrop_export/__init__.py
 else
     sed -i "s@$(echo "${OLD_VERSION}" | sed 's/\./\\./g')@$NEW_VERSION@g" securedrop_export/VERSION
+    sed -i "s@$(echo "${OLD_VERSION}" | sed 's/\./\\./g')@$NEW_VERSION@g" securedrop_export/__init__.py
 fi