Captures the stdout and stderr of the pre/post scripts into the log

src/documents/consumer.py

@@ -2,7 +2,8 @@ import datetime
 import hashlib
 import os
 import uuid
-from subprocess import Popen
+from subprocess import CompletedProcess
+from subprocess import run
 from typing import Optional
 from typing import Type
 
@@ -148,14 +149,21 @@ class Consumer(LoggingMixin):
         script_env["DOCUMENT_SOURCE_PATH"] = filepath_arg
 
         try:
-            Popen(
-                (
+            completed_proc = run(
+                args=[
                     settings.PRE_CONSUME_SCRIPT,
                     filepath_arg,
-                ),
+                ],
                 env=script_env,
-            ).wait()
-        except Exception as e:
+                capture_output=True,
+            )
+
+            self._log_script_outputs(completed_proc)
+
+            # Raises exception on non-zero output
+            completed_proc.check_returncode()
+
+        except Exception as e:  # pragma: nocover
             self._fail(
                 MESSAGE_PRE_CONSUME_SCRIPT_ERROR,
                 f"Error while executing pre-consume script: {e}",
@@ -208,8 +216,8 @@ class Consumer(LoggingMixin):
         script_env["DOCUMENT_ORIGINAL_FILENAME"] = str(document.original_filename)
 
         try:
-            Popen(
-                (
+            completed_proc = run(
+                args=[
                     settings.POST_CONSUME_SCRIPT,
                     str(document.pk),
                     document.get_public_filename(),
@@ -219,10 +227,17 @@ class Consumer(LoggingMixin):
                     reverse("document-thumb", kwargs={"pk": document.pk}),
                     str(document.correspondent),
                     str(",".join(document.tags.all().values_list("name", flat=True))),
-                ),
+                ],
                 env=script_env,
-            ).wait()
-        except Exception as e:
+                capture_output=True,
+            )
+
+            self._log_script_outputs(completed_proc)
+
+            # Raises exception on non-zero output
+            completed_proc.check_returncode()
+
+        except Exception as e:  # pragma: nocover
             self._fail(
                 MESSAGE_POST_CONSUME_SCRIPT_ERROR,
                 f"Error while executing post-consume script: {e}",
@@ -510,3 +525,31 @@ class Consumer(LoggingMixin):
         with open(source, "rb") as read_file:
             with open(target, "wb") as write_file:
                 write_file.write(read_file.read())
+
+    def _log_script_outputs(self, completed_process: CompletedProcess):
+        """
+        Decodes a process stdout and stderr streams and logs them to the main log
+        """
+        # Log what the script exited as
+        self.log(
+            "info",
+            f"{completed_process.args[0]} exited {completed_process.returncode}",
+        )
+
+        # Decode the output (if any)
+        stdout_str = completed_process.stdout.decode("utf8", errors="ignore").split(
+            "\n",
+        )
+        stderr_str = completed_process.stderr.decode("utf8", errors="ignore").split(
+            "\n",
+        )
+
+        if len(stdout_str):
+            self.log("info", "Script stdout:")
+            for line in stdout_str:
+                self.log("info", line)
+
+        if len(stderr_str):
+            self.log("warning", "Script stderr:")
+            for line in stderr_str:
+                self.log("warning", line)

src/documents/tests/test_consumer.py

@@ -2,7 +2,9 @@ import datetime
 import os
 import re
 import shutil
+import stat
 import tempfile
+from subprocess import CalledProcessError
 from unittest import mock
 from unittest.mock import MagicMock
 
@@ -801,7 +803,7 @@ class TestConsumerCreatedDate(DirectoriesMixin, TestCase):
 
 
 class PreConsumeTestCase(TestCase):
-    @mock.patch("documents.consumer.Popen")
+    @mock.patch("documents.consumer.run")
     @override_settings(PRE_CONSUME_SCRIPT=None)
     def test_no_pre_consume_script(self, m):
         c = Consumer()
@@ -809,7 +811,7 @@ class PreConsumeTestCase(TestCase):
         c.run_pre_consume_script()
         m.assert_not_called()
 
-    @mock.patch("documents.consumer.Popen")
+    @mock.patch("documents.consumer.run")
     @mock.patch("documents.consumer.Consumer._send_progress")
     @override_settings(PRE_CONSUME_SCRIPT="does-not-exist")
     def test_pre_consume_script_not_found(self, m, m2):
@@ -818,7 +820,7 @@ class PreConsumeTestCase(TestCase):
         c.path = "path-to-file"
         self.assertRaises(ConsumerError, c.run_pre_consume_script)
 
-    @mock.patch("documents.consumer.Popen")
+    @mock.patch("documents.consumer.run")
     def test_pre_consume_script(self, m):
         with tempfile.NamedTemporaryFile() as script:
             with override_settings(PRE_CONSUME_SCRIPT=script.name):
@@ -830,14 +832,45 @@ class PreConsumeTestCase(TestCase):
 
                 args, kwargs = m.call_args
 
-                command = args[0]
+                command = kwargs["args"]
 
                 self.assertEqual(command[0], script.name)
                 self.assertEqual(command[1], "path-to-file")
 
+    @mock.patch("documents.consumer.Consumer.log")
+    def test_script_with_output(self, mocked_log):
+        """
+        GIVEN:
+            - A script which outputs to stdout and stderr
+        WHEN:
+            - The script is executed as a consume script
+        THEN:
+            - The script's outputs are logged
+        """
+        with tempfile.NamedTemporaryFile(mode="w") as script:
+            # Write up a little script
+            with script.file as outfile:
+                outfile.write("#!/usr/bin/env bash\n")
+                outfile.write("echo This message goes to stdout\n")
+                outfile.write("echo This message goes to stderr >&2")
+
+            # Make the file executable
+            st = os.stat(script.name)
+            os.chmod(script.name, st.st_mode | stat.S_IEXEC)
+
+            with override_settings(PRE_CONSUME_SCRIPT=script.name):
+                c = Consumer()
+                c.path = "path-to-file"
+                c.run_pre_consume_script()
+
+                mocked_log.assert_called()
+
+                mocked_log.assert_any_call("info", "This message goes to stdout")
+                mocked_log.assert_any_call("warning", "This message goes to stderr")
+
 
 class PostConsumeTestCase(TestCase):
-    @mock.patch("documents.consumer.Popen")
+    @mock.patch("documents.consumer.run")
     @override_settings(POST_CONSUME_SCRIPT=None)
     def test_no_post_consume_script(self, m):
         doc = Document.objects.create(title="Test", mime_type="application/pdf")
@@ -858,7 +891,7 @@ class PostConsumeTestCase(TestCase):
         c.filename = "somefile.pdf"
         self.assertRaises(ConsumerError, c.run_post_consume_script, doc)
 
-    @mock.patch("documents.consumer.Popen")
+    @mock.patch("documents.consumer.run")
     def test_post_consume_script_simple(self, m):
         with tempfile.NamedTemporaryFile() as script:
             with override_settings(POST_CONSUME_SCRIPT=script.name):
@@ -868,7 +901,7 @@ class PostConsumeTestCase(TestCase):
 
                 m.assert_called_once()
 
-    @mock.patch("documents.consumer.Popen")
+    @mock.patch("documents.consumer.run")
     def test_post_consume_script_with_correspondent(self, m):
         with tempfile.NamedTemporaryFile() as script:
             with override_settings(POST_CONSUME_SCRIPT=script.name):
@@ -889,7 +922,7 @@ class PostConsumeTestCase(TestCase):
 
                 args, kwargs = m.call_args
 
-                command = args[0]
+                command = kwargs["args"]
 
                 self.assertEqual(command[0], script.name)
                 self.assertEqual(command[1], str(doc.pk))