Use wait_for_print method to ensure jobs are correctly transferred

securedrop_export/print/service.py

@@ -22,10 +22,10 @@ class Service:
     LASERJET_DRIVER = "/usr/share/cups/drv/hpcups.drv"
     LASERJET_PPD = "/usr/share/cups/model/hp-laserjet_6l.ppd"
 
-    def __init__(self, submission):
+    def __init__(self, submission, printer_timeout_seconds=PRINTER_WAIT_TIMEOUT):
         self.submission = submission
         self.printer_name = self.PRINTER_NAME
-        self.printer_wait_timeout = self.PRINTER_WAIT_TIMEOUT
+        self.printer_wait_timeout = printer_timeout_seconds  # Override during testing
 
     def print(self):
         """
@@ -258,6 +258,10 @@ def _print_file(self, file_to_print):
             command=["xpp", "-P", self.printer_name, file_to_print],
             error_status=Status.ERROR_PRINT,
         )
+        # This is an addition to ensure that the entire print job is transferred over.
+        # If the job is not fully transferred within the timeout window, the user
+        # will see an error message.
+        self._wait_for_print()
 
     def safe_check_call(
         self, command: str, error_status: Status, ignore_stderr_startswith=None

tests/print/test_service.py

@@ -39,6 +39,9 @@ def teardown_class(cls):
         cls.service = None
         cls.submission = None
 
+    def setup_method(self):
+        self.service.printer_wait_timeout = self.service.PRINTER_WAIT_TIMEOUT
+
     @mock.patch("subprocess.check_output", return_value=SAMPLE_OUTPUT_BROTHER_PRINTER)
     def test_get_good_printer_uri_laserjet(self, mocked_call):
         assert (
@@ -67,7 +70,8 @@ def test_print_all_methods_called(self):
         patch_setup.stop()
         patch_print.stop()
 
-    def test_printer_test_all_methods_called(self):
+    @mock.patch("securedrop_export.print.service.Service._wait_for_print")
+    def test_printer_preflight_all_methods_called(self, mock_wait):
         patch_setup = mock.patch.object(self.service, "_check_printer_setup")
 
         mock_setup = patch_setup.start()
@@ -80,7 +84,8 @@ def test_printer_test_all_methods_called(self):
 
         patch_setup.stop()
 
-    def test_print_all_checks_called(self):
+    @mock.patch("securedrop_export.print.service.Service._wait_for_print")
+    def test_print_testpage_all_checks_called(self, mock_wait):
         patch_setup = mock.patch.object(self.service, "_check_printer_setup")
         patch_print = mock.patch.object(self.service, "_print_test_page")
 
@@ -208,7 +213,7 @@ def test_safe_check_call_write_to_stderr_wrong_ignore_param(self):
 
         assert ex.value.sdstatus is Status.ERROR_PRINT
 
-    @mock.patch("time.sleep", return_value=None)
+    @mock.patch("securedrop_export.print.service.time.sleep", return_value=None)
     @mock.patch(
         "subprocess.check_output",
         side_effect=[
@@ -219,12 +224,12 @@ def test_safe_check_call_write_to_stderr_wrong_ignore_param(self):
     def test__wait_for_print(self, mock_subprocess, mock_time):
         assert self.service._wait_for_print()
 
-    @mock.patch("time.sleep", return_value=None)
     @mock.patch(
         "subprocess.check_output",
         side_effect=subprocess.CalledProcessError(1, "check_output"),
     )
-    def test__wait_for_print_print_exception(self, mock_subprocess, mock_time):
+    @mock.patch("time.sleep", return_value=None)
+    def test__wait_for_print_print_exception(self, mock_time, mock_subprocess):
         with pytest.raises(ExportException) as ex:
             self.service._wait_for_print()
 
@@ -233,16 +238,14 @@ def test__wait_for_print_print_exception(self, mock_subprocess, mock_time):
     @mock.patch(
         "subprocess.check_output", return_value=b"printer sdw-printer is busy\n"
     )
-    def test__wait_for_print_timeout_exception(self, mock_subprocess):
+    def test__wait_for_print_timeout_exception(self, mock_output):
         self.service.printer_wait_timeout = 1
 
         with pytest.raises(ExportException) as ex:
             self.service._wait_for_print()
 
         assert ex.value.sdstatus is Status.ERROR_PRINT
 
-        self.service.printer_wait_timeout = self.service.PRINTER_WAIT_TIMEOUT
-
     @pytest.mark.parametrize(
         "printers", [SAMPLE_OUTPUT_BROTHER_PRINTER, SAMPLE_OUTPUT_LASERJET_PRINTER]
     )
@@ -322,15 +325,17 @@ def test__install_printer_ppd_error_unsupported_uri(self):
             )
         assert ex.value.sdstatus is Status.ERROR_PRINTER_NOT_SUPPORTED
 
-    def test__print_test_page_calls_method(self):
+    @mock.patch("securedrop_export.print.service.Service._wait_for_print")
+    def test__print_test_page_calls_method(self, mock_wait):
         p = mock.patch.object(self.service, "_print_file")
         mock_print = p.start()
 
         self.service._print_test_page()
         mock_print.assert_called_once_with("/usr/share/cups/data/testprint")
         p.stop()
 
-    def test__print_all_files(self):
+    @mock.patch("securedrop_export.print.service.Service._wait_for_print")
+    def test__print_all_files(self, mock_wait):
         p = mock.patch.object(self.service, "_print_file")
         mock_print = p.start()
 
@@ -345,7 +350,8 @@ def test__print_all_files(self):
         )
         p.stop()
 
-    def test_open_office_file_convert_to_pdf(self):
+    @mock.patch("securedrop_export.print.service.Service._wait_for_print")
+    def test_open_office_file_convert_to_pdf(self, mock_wait):
         file = "/tmp/definitely-an-office-file.odt"
 
         with mock.patch.object(self.service, "safe_check_call") as scc, mock.patch(
@@ -391,3 +397,43 @@ def test_safe_check_call_has_error_in_stderr(self):
             self.service.safe_check_call(command="ls", error_status=Status.TEST_SUCCESS)
 
         assert ex.value.sdstatus is Status.TEST_SUCCESS
+
+    @mock.patch("securedrop_export.print.service.time.sleep", return_value=None)
+    @mock.patch(
+        "subprocess.check_output",
+        side_effect=[
+            b"printer sdw-printer is busy\n",
+            b"printer sdw-printer is idle\n",
+        ],
+    )
+    def test__wait_for_print_waits_correctly(self, mock_subprocess, mock_time):
+        file = "/tmp/happy-to-print-you.pdf"
+
+        with mock.patch.object(self.service, "safe_check_call") as scc, mock.patch(
+            "securedrop_export.print.service.logger.info"
+        ) as log:
+            self.service._print_file(file)
+
+        assert scc.call_count == 1
+        scc.assert_has_calls(
+            [
+                mock.call(
+                    command=[
+                        "xpp",
+                        "-P",
+                        "sdw-printer",
+                        "/tmp/happy-to-print-you.pdf",
+                    ],
+                    error_status=Status.ERROR_PRINT,
+                ),
+            ]
+        )
+        assert log.call_count == 4
+        log.assert_has_calls(
+            [
+                mock.call("Sending file to printer sdw-printer"),
+                mock.call("Running lpstat waiting for printer sdw-printer"),
+                mock.call("Running lpstat waiting for printer sdw-printer"),
+                mock.call("Print completed"),
+            ]
+        )