scheduled_messages: Remove separate logfile.

This is all captured in `events_deliver_scheduled_messages.log` (note
the leading `events_`) via supervisor.

zerver/actions/scheduled_messages.py

@@ -359,7 +359,7 @@ def send_failed_scheduled_message_notification(
 
 
 @transaction.atomic(durable=True)
-def try_deliver_one_scheduled_message(logger: logging.Logger) -> bool:
+def try_deliver_one_scheduled_message() -> bool:
     # Returns whether there was a scheduled message to attempt
     # delivery on, regardless of whether delivery succeeded.
     scheduled_message = (
@@ -375,7 +375,7 @@ def try_deliver_one_scheduled_message(logger: logging.Logger) -> bool:
     if scheduled_message is None:
         return False
 
-    logger.info(
+    logging.info(
         "Sending scheduled message %s with date %s (sender: %s)",
         scheduled_message.id,
         scheduled_message.scheduled_timestamp,
@@ -392,12 +392,12 @@ def try_deliver_one_scheduled_message(logger: logging.Logger) -> bool:
 
             if isinstance(e, JsonableError):
                 scheduled_message.failure_message = e.msg
-                logger.info("Failed with message: %s", e.msg)
+                logging.info("Failed with message: %s", e.msg)
             else:
                 # An unexpected failure; store and send user a generic
                 # internal server error in notification message.
                 scheduled_message.failure_message = _("Internal server error")
-                logger.exception(
+                logging.exception(
                     "Unexpected error sending scheduled message %s (sent: %s)",
                     scheduled_message.id,
                     was_delivered,

zerver/management/commands/deliver_scheduled_messages.py

@@ -1,21 +1,15 @@
-import logging
 import time
 from datetime import timedelta
 from typing import Any
 
-from django.conf import settings
 from django.utils.timezone import now as timezone_now
 from typing_extensions import override
 
 from zerver.actions.scheduled_messages import try_deliver_one_scheduled_message
-from zerver.lib.logging_util import log_to_file
 from zerver.lib.management import ZulipBaseCommand
 
+
 ## Setup ##
-logger = logging.getLogger(__name__)
-log_to_file(logger, settings.DELIVER_SCHEDULED_MESSAGES_LOG_PATH)
-
-
 class Command(ZulipBaseCommand):
     help = """Deliver scheduled messages from the ScheduledMessage table.
 Run this command under supervisor.
@@ -29,7 +23,7 @@ Usage: ./manage.py deliver_scheduled_messages
     def handle(self, *args: Any, **options: Any) -> None:
         try:
             while True:
-                if try_deliver_one_scheduled_message(logger):
+                if try_deliver_one_scheduled_message():
                     continue
 
                 # If there's no overdue scheduled messages, go to sleep until the next minute.

zerver/tests/test_scheduled_messages.py

@@ -3,7 +3,6 @@ import time
 from datetime import timedelta
 from io import StringIO
 from typing import TYPE_CHECKING, Any
-from unittest import mock
 
 import orjson
 import time_machine
@@ -104,9 +103,8 @@ class ScheduledMessageTest(ZulipTestCase):
         self.assert_json_success(result)
 
     def test_successful_deliver_stream_scheduled_message(self) -> None:
-        logger = mock.Mock()
         # No scheduled message
-        result = try_deliver_one_scheduled_message(logger)
+        result = try_deliver_one_scheduled_message()
         self.assertFalse(result)
 
         self.create_scheduled_message()
@@ -117,14 +115,17 @@ class ScheduledMessageTest(ZulipTestCase):
             minutes=1
         )
 
-        with time_machine.travel(more_than_scheduled_delivery_datetime, tick=False):
+        with (
-            result = try_deliver_one_scheduled_message(logger)
+            time_machine.travel(more_than_scheduled_delivery_datetime, tick=False),
+            self.assertLogs(level="INFO") as logs,
+        ):
+            result = try_deliver_one_scheduled_message()
             self.assertTrue(result)
-            logger.info.assert_called_once_with(
+            self.assertEqual(
-                "Sending scheduled message %s with date %s (sender: %s)",
+                logs.output,
-                scheduled_message.id,
+                [
-                scheduled_message.scheduled_timestamp,
+                    f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {scheduled_message.sender_id})"
-                scheduled_message.sender_id,
+                ],
             )
             scheduled_message.refresh_from_db()
             assert isinstance(scheduled_message.delivered_message_id, int)
@@ -137,9 +138,8 @@ class ScheduledMessageTest(ZulipTestCase):
             self.assertEqual(delivered_message.date_sent, more_than_scheduled_delivery_datetime)
 
     def test_successful_deliver_direct_scheduled_message(self) -> None:
-        logger = mock.Mock()
         # No scheduled message
-        self.assertFalse(try_deliver_one_scheduled_message(logger))
+        self.assertFalse(try_deliver_one_scheduled_message())
 
         content = "Test message"
         scheduled_delivery_datetime = timezone_now() + timedelta(minutes=5)
@@ -155,14 +155,17 @@ class ScheduledMessageTest(ZulipTestCase):
         # mock current time to be greater than the scheduled time.
         more_than_scheduled_delivery_datetime = scheduled_delivery_datetime + timedelta(minutes=1)
 
-        with time_machine.travel(more_than_scheduled_delivery_datetime, tick=False):
+        with (
-            result = try_deliver_one_scheduled_message(logger)
+            time_machine.travel(more_than_scheduled_delivery_datetime, tick=False),
+            self.assertLogs(level="INFO") as logs,
+        ):
+            result = try_deliver_one_scheduled_message()
             self.assertTrue(result)
-            logger.info.assert_called_once_with(
+            self.assertEqual(
-                "Sending scheduled message %s with date %s (sender: %s)",
+                logs.output,
-                scheduled_message.id,
+                [
-                scheduled_message.scheduled_timestamp,
+                    f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {scheduled_message.sender_id})"
-                scheduled_message.sender_id,
+                ],
             )
             scheduled_message.refresh_from_db()
             assert isinstance(scheduled_message.delivered_message_id, int)
@@ -192,9 +195,8 @@ class ScheduledMessageTest(ZulipTestCase):
         self.assert_json_error(updated_response, "Scheduled message was already sent")
 
     def test_successful_deliver_direct_scheduled_message_to_self(self) -> None:
-        logger = mock.Mock()
         # No scheduled message
-        self.assertFalse(try_deliver_one_scheduled_message(logger))
+        self.assertFalse(try_deliver_one_scheduled_message())
 
         content = "Test message to self"
         scheduled_delivery_datetime = timezone_now() + timedelta(minutes=5)
@@ -209,14 +211,17 @@ class ScheduledMessageTest(ZulipTestCase):
         # mock current time to be greater than the scheduled time.
         more_than_scheduled_delivery_datetime = scheduled_delivery_datetime + timedelta(minutes=1)
 
-        with time_machine.travel(more_than_scheduled_delivery_datetime, tick=False):
+        with (
-            result = try_deliver_one_scheduled_message(logger)
+            time_machine.travel(more_than_scheduled_delivery_datetime, tick=False),
+            self.assertLogs(level="INFO") as logs,
+        ):
+            result = try_deliver_one_scheduled_message()
             self.assertTrue(result)
-            logger.info.assert_called_once_with(
+            self.assertEqual(
-                "Sending scheduled message %s with date %s (sender: %s)",
+                logs.output,
-                scheduled_message.id,
+                [
-                scheduled_message.scheduled_timestamp,
+                    f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {scheduled_message.sender_id})"
-                scheduled_message.sender_id,
+                ],
             )
             scheduled_message.refresh_from_db()
             assert isinstance(scheduled_message.delivered_message_id, int)
@@ -232,28 +237,24 @@ class ScheduledMessageTest(ZulipTestCase):
             self.assertFalse(sender_user_message.flags.read)
 
     def verify_deliver_scheduled_message_failure(
-        self, scheduled_message: ScheduledMessage, logger: mock.Mock, expected_failure_message: str
+        self, scheduled_message: ScheduledMessage, expected_failure_message: str
     ) -> None:
-        result = try_deliver_one_scheduled_message(logger)
+        with self.assertLogs(level="INFO") as logs:
+            result = try_deliver_one_scheduled_message()
         self.assertTrue(result)
         scheduled_message.refresh_from_db()
         self.assertEqual(scheduled_message.failure_message, expected_failure_message)
-        calls = [
+        self.assertEqual(
-            mock.call(
+            logs.output,
-                "Sending scheduled message %s with date %s (sender: %s)",
+            [
-                scheduled_message.id,
+                f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {scheduled_message.sender_id})",
-                scheduled_message.scheduled_timestamp,
+                f"INFO:root:Failed with message: {scheduled_message.failure_message}",
-                scheduled_message.sender_id,
+            ],
-            ),
+        )
-            mock.call("Failed with message: %s", scheduled_message.failure_message),
-        ]
-        logger.info.assert_has_calls(calls)
-        self.assertEqual(logger.info.call_count, 2)
         self.assertTrue(scheduled_message.failed)
 
     def test_too_late_to_deliver_scheduled_message(self) -> None:
         expected_failure_message = "Message could not be sent at the scheduled time."
-        logger = mock.Mock()
         self.create_scheduled_message()
         scheduled_message = self.last_scheduled_message()
 
@@ -263,7 +264,7 @@ class ScheduledMessageTest(ZulipTestCase):
 
         with time_machine.travel(too_late_to_send_message_datetime, tick=False):
             self.verify_deliver_scheduled_message_failure(
-                scheduled_message, logger, expected_failure_message
+                scheduled_message, expected_failure_message
             )
 
         # Verify that the user was sent a message informing them about
@@ -276,7 +277,6 @@ class ScheduledMessageTest(ZulipTestCase):
 
     def test_realm_deactivated_failed_to_deliver_scheduled_message(self) -> None:
         expected_failure_message = "This organization has been deactivated"
-        logger = mock.Mock()
         self.create_scheduled_message()
         scheduled_message = self.last_scheduled_message()
 
@@ -294,7 +294,7 @@ class ScheduledMessageTest(ZulipTestCase):
             scheduled_message.realm.deactivated = True
             scheduled_message.realm.save()
             self.verify_deliver_scheduled_message_failure(
-                scheduled_message, logger, expected_failure_message
+                scheduled_message, expected_failure_message
             )
 
         # Verify that no failed scheduled message notification was sent.
@@ -305,7 +305,6 @@ class ScheduledMessageTest(ZulipTestCase):
 
     def test_sender_deactivated_failed_to_deliver_scheduled_message(self) -> None:
         expected_failure_message = "Account is deactivated"
-        logger = mock.Mock()
         self.create_scheduled_message()
         scheduled_message = self.last_scheduled_message()
 
@@ -322,7 +321,7 @@ class ScheduledMessageTest(ZulipTestCase):
             scheduled_message = self.last_scheduled_message()
             change_user_is_active(scheduled_message.sender, False)
             self.verify_deliver_scheduled_message_failure(
-                scheduled_message, logger, expected_failure_message
+                scheduled_message, expected_failure_message
             )
 
         # Verify that no failed scheduled message notification was sent.
@@ -334,7 +333,6 @@ class ScheduledMessageTest(ZulipTestCase):
     def test_delivery_type_reminder_failed_to_deliver_scheduled_message_unknown_exception(
         self,
     ) -> None:
-        logger = mock.Mock()
         self.create_scheduled_message()
         scheduled_message = self.last_scheduled_message()
 
@@ -346,20 +344,19 @@ class ScheduledMessageTest(ZulipTestCase):
             scheduled_message = self.last_scheduled_message()
             scheduled_message.delivery_type = ScheduledMessage.REMIND
             scheduled_message.save()
-            result = try_deliver_one_scheduled_message(logger)
+            with self.assertLogs(level="INFO") as logs:
+                result = try_deliver_one_scheduled_message()
             self.assertTrue(result)
             scheduled_message.refresh_from_db()
-            logger.info.assert_called_once_with(
+            self.assert_length(logs.output, 2)
-                "Sending scheduled message %s with date %s (sender: %s)",
+            self.assertEqual(
-                scheduled_message.id,
+                logs.output[0],
-                scheduled_message.scheduled_timestamp,
+                f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {scheduled_message.sender_id})",
-                scheduled_message.sender_id,
+            )
+            self.assertTrue(
+                logs.output[1].startswith(
+                    f"ERROR:root:Unexpected error sending scheduled message {scheduled_message.id} (sent: {scheduled_message.delivered})\nTraceback (most recent call last)"
                 )
-            logger.exception.assert_called_once_with(
-                "Unexpected error sending scheduled message %s (sent: %s)",
-                scheduled_message.id,
-                scheduled_message.delivered,
-                stack_info=True,
             )
             self.assertTrue(scheduled_message.failed)
 
@@ -373,7 +370,6 @@ class ScheduledMessageTest(ZulipTestCase):
 
     def test_editing_failed_send_scheduled_message(self) -> None:
         expected_failure_message = "Message could not be sent at the scheduled time."
-        logger = mock.Mock()
         self.create_scheduled_message()
         scheduled_message = self.last_scheduled_message()
 
@@ -383,7 +379,7 @@ class ScheduledMessageTest(ZulipTestCase):
 
         with time_machine.travel(too_late_to_send_message_datetime, tick=False):
             self.verify_deliver_scheduled_message_failure(
-                scheduled_message, logger, expected_failure_message
+                scheduled_message, expected_failure_message
             )
 
             # After verifying the scheduled message failed to be sent:

zproject/computed_settings.py

@@ -754,7 +754,6 @@ WEBHOOK_ANOMALOUS_PAYLOADS_LOG_PATH = zulip_path("/var/log/zulip/webhooks_anomal
 WEBHOOK_UNSUPPORTED_EVENTS_LOG_PATH = zulip_path("/var/log/zulip/webhooks_unsupported_events.log")
 SOFT_DEACTIVATION_LOG_PATH = zulip_path("/var/log/zulip/soft_deactivation.log")
 TRACEMALLOC_DUMP_DIR = zulip_path("/var/log/zulip/tracemalloc")
-DELIVER_SCHEDULED_MESSAGES_LOG_PATH = zulip_path("/var/log/zulip/deliver_scheduled_messages.log")
 RETENTION_LOG_PATH = zulip_path("/var/log/zulip/message_retention.log")
 AUTH_LOG_PATH = zulip_path("/var/log/zulip/auth.log")
 SCIM_LOG_PATH = zulip_path("/var/log/zulip/scim.log")