Address mounting race condition by checking udisks info prior to atte…

…mpting mount.

Pass export_error flag to cleanup method and flush stdout/err before
exit.

export/securedrop_export/disk/cli.py

@@ -2,7 +2,9 @@
 import logging
 import os
 import pexpect
+import re
 import subprocess
+import time
 
 from typing import Optional, Union
 
@@ -230,13 +232,13 @@ def unlock_volume(self, volume: Volume, encryption_key: str) -> MountedVolume:
         logger.debug("Unlocking volume {}".format(volume.device_name))
 
         command = f"udisksctl unlock --block-device {volume.device_name}"
-        prompt = ["Passphrase\: ", pexpect.EOF, pexpect.TIMEOUT]
+        prompt = ["Passphrase: ", pexpect.EOF, pexpect.TIMEOUT]
         expected = [
-            f"Unlocked {volume.device_name} as (.*)",
-            "GDBus.Error\:org.freedesktop.UDisks2.Error.Failed\: Device "  # string continues
-            f"{volume.device_name} is already unlocked as (.*)",
-            "GDBus.Error\:org.freedesktop.UDisks2.Error.Failed\: Error "  # string continues
-            f"unlocking {volume.device_name}\: Failed to activate device\: Incorrect passphrase",
+            f"Unlocked {volume.device_name} as (.*)\.",
+            "GDBus.Error:org.freedesktop.UDisks2.Error.Failed: Device "  # string continues
+            f"{volume.device_name} is already unlocked as (.*)\.",
+            "GDBus.Error:org.freedesktop.UDisks2.Error.Failed: Error "  # string continues
+            f"unlocking {volume.device_name}: Failed to activate device: Incorrect passphrase",
             pexpect.EOF,
             pexpect.TIMEOUT,
         ]
@@ -257,10 +259,10 @@ def unlock_volume(self, volume: Volume, encryption_key: str) -> MountedVolume:
                 logger.debug(f"Device is unlocked as {dm_name}")
 
                 child.close()
-                if (child.exitstatus) != 0:
+                if (child.exitstatus) not in (0, 1):
                     logger.warning(f"pexpect: child exited with {child.exitstatus}")
 
-                # The mapped_name format here is /dev/dm-X
+                # dm_name format is /dev/dm-X
                 return self._mount_volume(volume, dm_name)
 
             elif index == 2:
@@ -288,37 +290,67 @@ def _mount_volume(self, volume: Volume, full_unlocked_name: str) -> MountedVolum
         in the list of results to check for. (See
         https://pexpect.readthedocs.io/en/stable/api/pexpect.html#pexpect.spawn.expect)
         """
-        command = f"udisksctl mount --block-device {full_unlocked_name}"
-        expected = [
-            "Mounted .* at \(.*\)",
 
-            # Error mounting /dev/dm-0: GDBus.Error:org.freedesktop.UDisks2.Error.AlreadyMounted: Device /dev/dm-0 is already mounted at `/media/user/tx2\'
-            f"Error mounting {full_unlocked_name}\: GDBus.Error\:org."  # string continues
-            "freedesktop.UDisks2.Error.AlreadyMounted\: "  # string continues
-            "Device .* is already mounted at `(.*)\'",
+        info = f"udisksctl info --block-device {volume.device_name}"
+        # \x1b[37mPreferredDevice:\x1b[0m            /dev/sdaX\r\n
+        expected_info = [
+            f"PreferredDevice:[\t+]{volume.device_name}\r\n",
+            "Error looking up object for device",
+            pexpect.EOF,
+            pexpect.TIMEOUT,
+        ]
+        max_retries = 3
+
+        unlock = f"udisksctl mount --block-device {full_unlocked_name}"
+        expected_unlock = [
+            f"Mounted {full_unlocked_name} at (.*)",
+            f"Error mounting {full_unlocked_name}: GDBus.Error:org."  # string continues
+            "freedesktop.UDisks2.Error.AlreadyMounted: "  # string continues
+            "Device .* is already mounted at `(.*)'",
+            f"Error looking up object for device {full_unlocked_name}.",
             pexpect.EOF,
             pexpect.TIMEOUT,
         ]
         mountpoint = None
 
+        logger.debug(f"Check to make sure udisks identified the device")
+        for attempt in range(max_retries):
+            child = pexpect.spawn(info)
+            index = child.expect(expected_info)
+            child.close()
+
+            if index != 0:
+                logger.debug(f"index {index}")
+                print(f"udisks can't identify {volume.device_name}, retrying...")
+                logger.warning(
+                    f"udisks can't identify {volume.device_name}, retrying..."
+                )
+                time.sleep(1)
+            else:
+                print(f"udisks found {volume.device_name}")
+
         logger.info(f"Mount {full_unlocked_name} using udisksctl")
-        child = pexpect.spawn(command)
-        index = child.expect(expected)
+        child = pexpect.spawn(unlock)
+        index = child.expect(expected_unlock)
 
-        logger.debug(f"child: {str(child.match)}, before: {child.before}, after: {child.after}")
+        logger.debug(
+            f"child: {str(child.match)}, before: {child.before}, after: {child.after}"
+        )
 
         if index == 0:
             # As above, we know the format
-            mountpoint = child.match.group(1).decode("utf-8")
+            mountpoint = child.match.group(1).decode("utf-8").strip()
             logger.debug(f"Successfully mounted device at {mountpoint}")
 
         elif index == 1:
             # Mountpoint needs a bit of help. It arrives in the form `/path/to/mountpoint'.
             # including the one backtick, single quote, and the period
-
-            mountpoint = child.match.group(1).decode("utf-8")
+            mountpoint = child.match.group(1).decode("utf-8").strip()
             logger.debug(f"Device already mounted at {mountpoint}")
 
+        elif index == 2:
+            logger.debug("Device is not ready")
+
         child.close()
 
         if mountpoint:
@@ -340,11 +372,15 @@ def write_data_to_device(
     ):
         """
         Move files to drive (overwrites files with same filename) and unmount drive.
+
         Drive is unmounted and files are cleaned up as part of the `finally` block to ensure
         that cleanup happens even if export fails or only partially succeeds.
         """
 
         try:
+            # Flag to pass to cleanup method
+            is_error = False
+
             target_path = os.path.join(device.mountpoint, submission_target_dirname)
             subprocess.check_call(["mkdir", target_path])
 
@@ -358,28 +394,44 @@ def write_data_to_device(
 
         except (subprocess.CalledProcessError, OSError) as ex:
             logger.error(ex)
+
+            # Ensure we report an export error out after cleanup
+            is_error = True
             raise ExportException(sdstatus=Status.ERROR_EXPORT) from ex
 
         finally:
-            self.cleanup(device, submission_tmpdir)
+            self.cleanup(device, submission_tmpdir, is_error)
 
-    def cleanup(self, volume: MountedVolume, submission_tmpdir: str):
+    def cleanup(
+        self,
+        volume: MountedVolume,
+        submission_tmpdir: str,
+        is_error: bool = False,
+        should_close_volume: bool = True,
+    ):
         """
         Post-export cleanup method. Unmount and lock drive and remove temporary
-        directory. Currently called at end of `write_data_to_device()` to ensure
-        device is always locked after export.
+        directory.
+
+        Raises ExportException if errors during cleanup are encountered.
 
-        Raise ExportException if errors during cleanup are encountered.
+        Method is called whether or not export succeeds; if `is_error` is True,
+        will report export error status on error (insted of cleanup status).
         """
+        error_status = Status.ERROR_EXPORT if is_error else Status.ERROR_EXPORT_CLEANUP
+
         logger.debug("Syncing filesystems")
         try:
             subprocess.check_call(["sync"])
-            self._close_volume(volume)
             self._remove_temp_directory(submission_tmpdir)
 
+            # Future configurable option
+            if should_close_volume:
+                self._close_volume(volume)
+
         except subprocess.CalledProcessError as ex:
             logger.error("Error syncing filesystem")
-            raise ExportException(sdstatus=Status.ERROR_EXPORT_CLEANUP) from ex
+            raise ExportException(sdstatus=error_status) from ex
 
     def _close_volume(self, mv: MountedVolume) -> Volume:
         """
@@ -401,8 +453,7 @@ def _close_volume(self, mv: MountedVolume) -> Volume:
                 logger.error(ex)
                 logger.error("Error unmounting device")
 
-                # todo: return 'device busy' code
-                raise ExportException(sdstatus=Status.ERROR_EXPORT_CLEANUP) from ex
+                raise ExportException(sdstatus=Status.ERROR_UNMOUNT_VOLUME_BUSY) from ex
         else:
             logger.info("Mountpoint does not exist; volume was already unmounted")
 

export/securedrop_export/main.py

@@ -74,16 +74,18 @@ def entrypoint():
                 submission.set_metadata(metadata)
                 logger.info(f"Start {metadata.command.value} service")
                 status = _start_service(submission)
+                logger.info(f"Status: {status.value}")
 
-    except ExportException as ex:
-        logger.error(f"Encountered exception {ex.sdstatus.value}, exiting")
+    # Gotta catch'em all. A nonzero exit status will cause other programs
+    # to try to handle the files, which we don't want.
+    except Exception as ex:
         logger.error(ex)
-        status = ex.sdstatus
-
-    except Exception as exc:
-        logger.error("Encountered exception during export, exiting")
-        logger.error(exc)
-        status = Status.ERROR_GENERIC
+        if isinstance(ex, ExportException):
+            logger.error(f"Encountered exception {ex.sdstatus.value}, exiting")
+            status = ex.sdstatus
+        else:
+            logger.error("Encountered exception during export, exiting")
+            status = Status.ERROR_GENERIC
 
     finally:
         _exit_gracefully(submission, status)
@@ -156,16 +158,12 @@ def _start_service(submission: Archive) -> BaseStatus:
     )
 
 
-def _exit_gracefully(submission: Archive, status: Optional[BaseStatus] = None):
+def _exit_gracefully(submission: Archive, status: BaseStatus):
     """
     Write status code, ensure file cleanup, and exit with return code 0.
     Non-zero exit values will cause the system to try alternative
     solutions for mimetype handling, which we want to avoid.
     """
-    if status:
-        logger.info(f"Exit gracefully with status: {status.value}")
-    else:
-        logger.info("Exit gracefully (no status code supplied)")
     try:
         # If the file archive was extracted, delete before returning
         if submission and os.path.isdir(submission.tmpdir):
@@ -182,21 +180,30 @@ def _exit_gracefully(submission: Archive, status: Optional[BaseStatus] = None):
         sys.exit(0)
 
 
-def _write_status(status: Optional[BaseStatus]):
+def _write_status(status: BaseStatus):
     """
-    Write status string to stderr.
+    Write status string to stderr. Flush stderr and stdout before we exit.
     """
-    if status:
-        logger.info(f"Write status {status.value}")
-
+    logger.info(f"Write status {status.value}")
+    try:
         # First we will log errors from stderr elsewhere
         tmp_stderr = io.StringIO()
-        with contextlib.redirect_stderr(tmp_stderr):
+        tmp_stdout = io.StringIO()
+        with contextlib.redirect_stderr(tmp_stderr), contextlib.redirect_stdout(
+            tmp_stdout
+        ):
             sys.stderr.flush()
-        if tmp_stderr.getvalue() is not None:
-            logger.error(f"Error-capture: {tmp_stderr.getvalue()}")
+            sys.stdout.flush()
+            if len(tmp_stderr.getvalue()) > 0:
+                logger.error(f"Error capture: {tmp_stderr.getvalue()}")
+            if len(tmp_stdout.getvalue()) > 0:
+                logger.info(f"stdout capture: {tmp_stderr.getvalue()}")
 
         sys.stderr.write(status.value)
         sys.stderr.write("\n")
-    else:
-        logger.info("No status value supplied")
+        sys.stderr.flush()
+        sys.stdout.flush()
+    except BrokenPipeError:
+        devnull = os.open(os.devnull, os.O_WRONLY)
+        os.dup2(devnull, sys.stdout.fileno())
+        os.dup2(devnull, sys.stderr.fileno())

export/tests/disk/test_cli.py

@@ -207,10 +207,7 @@ def test_unlock_success(self, mock_p):
             mock_mount.return_value = mv
             result = self.cli.unlock_volume(vol, "a passw0rd!")
 
-            mock_mount.assert_called_once_with(
-                vol,
-                "/dev/dm-0"
-            )
+            mock_mount.assert_called_once_with(vol, "/dev/dm-0")
             assert isinstance(result, MountedVolume)
 
     @mock.patch("pexpect.spawn")
@@ -249,7 +246,7 @@ def test_unlock_luks_bad_passphrase(self, mock_p):
         # unlock_volume method (list item with index 1 is the "Bad passphrase"
         # error)
         child.expect.side_effect = [0, 2]
-        child.match = mock.MagicMock(spec=re.Match) 
+        child.match = mock.MagicMock(spec=re.Match)
         child.match.group.return_value = b"/media/usb"
 
         vol = Volume(_DEFAULT_USB_DEVICE, EncryptionScheme.LUKS)
@@ -266,7 +263,7 @@ def test_unlock_fail(self, mock_p):
         # This is derived from the "expected" list in the unlock_volume method
         # (list item with index 3 is the "pexpect.EOF" error)
         child.expect.side_effect = [0, 3]
-        child.match = mock.MagicMock(spec=re.Match) 
+        child.match = mock.MagicMock(spec=re.Match)
         child.match.group.return_value = b"/media/usb"
 
         vol = Volume(_DEFAULT_USB_DEVICE, EncryptionScheme.LUKS)
@@ -280,7 +277,7 @@ def test_unlock_fail(self, mock_p):
     def test__mount_volume_already_mounted(self, mock_p):
         child = mock_p()
         child.expect.return_value = 1
-        child.match = mock.MagicMock(spec=re.Match) 
+        child.match = mock.MagicMock(spec=re.Match)
         child.match.group.return_value = b"/media/usb"
 
         md = MountedVolume(
@@ -298,7 +295,7 @@ def test__mount_volume_already_mounted(self, mock_p):
     def test__mount_volume_success(self, mock_p):
         child = mock_p()
         child.expect.return_value = 0
-        child.match = mock.MagicMock(spec=re.Match) 
+        child.match = mock.MagicMock(spec=re.Match)
         child.match.group.return_value = b"/media/usb"
 
         md = MountedVolume(
@@ -401,6 +398,19 @@ def test_cleanup_error(self, mock_popen):
             self.cli.cleanup(mock_volume, submission.tmpdir)
         assert ex.value.sdstatus is Status.ERROR_EXPORT_CLEANUP
 
+    @mock.patch(
+        "subprocess.check_call",
+        side_effect=subprocess.CalledProcessError(1, "check_call"),
+    )
+    def test_cleanup_error_reports_exporterror_if_flagged(self, mock_popen):
+        submission = Archive("testfile")
+        mock_volume = mock.MagicMock(Volume)
+
+        with pytest.raises(ExportException) as ex:
+            self.cli.cleanup(mock_volume, submission.tmpdir, is_error=True)
+        assert ex.value.sdstatus is Status.ERROR_EXPORT
+
+
     @mock.patch("os.path.exists", return_value=False)
     @mock.patch("subprocess.check_call", return_value=0)
     def test_cleanup(self, mock_subprocess, mocked_path):
@@ -431,14 +441,17 @@ def test_cleanup(self, mock_subprocess, mocked_path):
         remove_tmpdir_patch.stop()
 
     @mock.patch("pexpect.spawn")
-    def test_parse_correct_mountpoint_from_pexpect(
-        self, mock_pexpect
-    ):
+    def test_parse_correct_mountpoint_from_pexpect(self, mock_pexpect):
         child = mock_pexpect()
         child.expect.return_value = 1
-        child.match.return_value = re.match(r"`(\w+)'\.$".encode("utf-8"), f"Error mounting /dev/dm-1\: GDBus.Error\:org."
+        child.match.return_value = re.match(
+            r"`(\w+)'\.\r\n".encode("utf-8"),
+            "Error mounting /dev/dm-1: GDBus.Error:org."
             "freedesktop.UDisks2.Error.AlreadyMounted: "
-            "Device /dev/sda1 is already mounted at `/dev/dm-0'.".encode("utf-8"))
-
-        mv = self.cli._mount_volume(Volume("/dev/sda1", EncryptionScheme.VERACRYPT), "/dev/dm-1")
-        assert mv.unlocked_name == "/dev/dm-0"
+            "Device /dev/sda1 is already mounted at `/dev/dm-0'.\r\n".encode("utf-8"),
+        )
+
+        mv = self.cli._mount_volume(
+            Volume("/dev/sda1", EncryptionScheme.VERACRYPT), "/dev/dm-1"
+        )
+        assert mv.unlocked_name == "/dev/dm-0"