From 4b4b6c5ebe0880c7e8f79c659d23ebdce0dab309 Mon Sep 17 00:00:00 2001 From: Alex Vandiver Date: Fri, 4 Oct 2024 20:05:05 +0000 Subject: [PATCH] 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 | 8 +- .../commands/deliver_scheduled_messages.py | 10 +- zerver/tests/test_scheduled_messages.py | 118 +++++++++--------- zproject/computed_settings.py | 1 - 4 files changed, 63 insertions(+), 74 deletions(-) diff --git a/zerver/actions/scheduled_messages.py b/zerver/actions/scheduled_messages.py index bc03155a89..b3d372096c 100644 --- a/zerver/actions/scheduled_messages.py +++ b/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, diff --git a/zerver/management/commands/deliver_scheduled_messages.py b/zerver/management/commands/deliver_scheduled_messages.py index dc079047a6..76ea70af49 100644 --- a/zerver/management/commands/deliver_scheduled_messages.py +++ b/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. diff --git a/zerver/tests/test_scheduled_messages.py b/zerver/tests/test_scheduled_messages.py index 03ee1c115d..06298e8411 100644 --- a/zerver/tests/test_scheduled_messages.py +++ b/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): - result = try_deliver_one_scheduled_message(logger) + with ( + 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( - "Sending scheduled message %s with date %s (sender: %s)", - scheduled_message.id, - scheduled_message.scheduled_timestamp, - scheduled_message.sender_id, + self.assertEqual( + logs.output, + [ + f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {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): - result = try_deliver_one_scheduled_message(logger) + with ( + 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( - "Sending scheduled message %s with date %s (sender: %s)", - scheduled_message.id, - scheduled_message.scheduled_timestamp, - scheduled_message.sender_id, + self.assertEqual( + logs.output, + [ + f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {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): - result = try_deliver_one_scheduled_message(logger) + with ( + 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( - "Sending scheduled message %s with date %s (sender: %s)", - scheduled_message.id, - scheduled_message.scheduled_timestamp, - scheduled_message.sender_id, + self.assertEqual( + logs.output, + [ + f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {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 = [ - mock.call( - "Sending scheduled message %s with date %s (sender: %s)", - scheduled_message.id, - scheduled_message.scheduled_timestamp, - 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.assertEqual( + logs.output, + [ + f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {scheduled_message.sender_id})", + f"INFO:root:Failed with message: {scheduled_message.failure_message}", + ], + ) 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( - "Sending scheduled message %s with date %s (sender: %s)", - scheduled_message.id, - scheduled_message.scheduled_timestamp, - scheduled_message.sender_id, + self.assert_length(logs.output, 2) + self.assertEqual( + logs.output[0], + f"INFO:root:Sending scheduled message {scheduled_message.id} with date {scheduled_message.scheduled_timestamp} (sender: {scheduled_message.sender_id})", ) - 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( + logs.output[1].startswith( + f"ERROR:root:Unexpected error sending scheduled message {scheduled_message.id} (sent: {scheduled_message.delivered})\nTraceback (most recent call last)" + ) ) 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: diff --git a/zproject/computed_settings.py b/zproject/computed_settings.py index b3e798a38d..407713c3ea 100644 --- a/zproject/computed_settings.py +++ b/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")