diff --git a/src/documents/consumer.py b/src/documents/consumer.py index f542a1d98..7c0cbd2d3 100644 --- a/src/documents/consumer.py +++ b/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) diff --git a/src/documents/tests/test_consumer.py b/src/documents/tests/test_consumer.py index 3b94b889b..4a3908f8e 100644 --- a/src/documents/tests/test_consumer.py +++ b/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))