logging: replace mock.patch() for logging with assertLogs()

This commit removes mock.patch with assertLogs().

* Adds return value to do_rest_call() in outgoing_webhook.py, to
  support asserting log output in test_outgoing_webhook_system.py.

* Logs are not asserted in test_realm.py because it would require to users
  to be queried using users=User.objects.filter(realm=realm) and the order
  of resulting queryset varies for each run.

* In test_decorators.py, replacement of mock.patch is not done because
  I'm not sure if it's worth the effort to replace it as it's a return
  value of a function.

Tweaked by tabbott to set proper mypy types.

analytics/tests/test_views.py

@@ -319,16 +319,19 @@ class TestGetChartData(ZulipTestCase):
 
         realm.date_created = timezone_now() - timedelta(days=3)
         realm.save(update_fields=["date_created"])
-        with mock.patch('logging.warning'):
+        with self.assertLogs(level="WARNING") as m:
-            result = self.client_get('/json/analytics/chart_data',
+            result = self.client_get('/json/analytics/chart_data', {'chart_name': 'messages_sent_over_time'})
-                                     {'chart_name': 'messages_sent_over_time'})
+            self.assertEqual(m.output, [f"WARNING:root:User from realm zulip attempted to access /stats, but the computed start time: {realm.date_created} (creation of realm or installation) is later than the computed end time: 0001-01-01 00:00:00+00:00 (last successful analytics update). Is the analytics cron job running?"])
+
         self.assert_json_error_contains(result, 'No analytics data available')
 
         realm.date_created = timezone_now() - timedelta(days=1, hours=2)
         realm.save(update_fields=["date_created"])
-        with mock.patch('logging.warning'):
+        with self.assertLogs(level="WARNING") as m:
             result = self.client_get('/json/analytics/chart_data',
                                      {'chart_name': 'messages_sent_over_time'})
+            self.assertEqual(m.output, [f"WARNING:root:User from realm zulip attempted to access /stats, but the computed start time: {realm.date_created} (creation of realm or installation) is later than the computed end time: 0001-01-01 00:00:00+00:00 (last successful analytics update). Is the analytics cron job running?"])
+
         self.assert_json_error_contains(result, 'No analytics data available')
 
         realm.date_created = timezone_now() - timedelta(days=1, minutes=10)
@@ -349,9 +352,11 @@ class TestGetChartData(ZulipTestCase):
 
         realm.date_created = timezone_now() - timedelta(days=3)
         realm.save(update_fields=["date_created"])
-        with mock.patch('logging.warning'):
+        with self.assertLogs(level="WARNING") as m:
             result = self.client_get('/json/analytics/chart_data',
                                      {'chart_name': 'messages_sent_over_time'})
+            self.assertEqual(m.output, [f"WARNING:root:User from realm zulip attempted to access /stats, but the computed start time: {realm.date_created} (creation of realm or installation) is later than the computed end time: {end_time} (last successful analytics update). Is the analytics cron job running?"])
+
         self.assert_json_error_contains(result, 'No analytics data available')
 
         realm.date_created = timezone_now() - timedelta(days=1, minutes=10)
@@ -372,9 +377,11 @@ class TestGetChartData(ZulipTestCase):
 
         realm.date_created = timezone_now() - timedelta(days=1, hours=2)
         realm.save(update_fields=["date_created"])
-        with mock.patch('logging.warning'):
+        with self.assertLogs(level="WARNING") as m:
             result = self.client_get('/json/analytics/chart_data',
                                      {'chart_name': 'messages_sent_over_time'})
+            self.assertEqual(m.output, [f"WARNING:root:User from realm zulip attempted to access /stats, but the computed start time: {realm.date_created} (creation of realm or installation) is later than the computed end time: {end_time} (last successful analytics update). Is the analytics cron job running?"])
+
         self.assert_json_error_contains(result, 'No analytics data available')
 
         realm.date_created = timezone_now() - timedelta(days=1, minutes=10)

zerver/lib/outgoing_webhook.py

@@ -295,7 +295,8 @@ def process_success_response(event: Dict[str, Any],
 def do_rest_call(base_url: str,
                  request_data: Any,
                  event: Dict[str, Any],
-                 service_handler: Any) -> None:
+                 service_handler: Any) -> Optional[Response]:
+    """Returns response of call if no exception occurs."""
     try:
         response = service_handler.send_data_to_server(
             base_url=base_url,
@@ -313,7 +314,7 @@ def do_rest_call(base_url: str,
             failure_message = f"Third party responded with {response.status_code}"
             fail_with_message(event, failure_message)
             notify_bot_owner(event, response.status_code, response.content)
-
+        return response
     except requests.exceptions.Timeout:
         logging.info(
             "Trigger event %s on %s timed out. Retrying",
@@ -321,12 +322,14 @@ def do_rest_call(base_url: str,
         )
         failure_message = "A timeout occurred."
         request_retry(event, failure_message=failure_message)
+        return None
 
     except requests.exceptions.ConnectionError:
         logging.info("Trigger event %s on %s resulted in a connection error. Retrying",
                      event["command"], event['service_name'])
         failure_message = "A connection error occurred. Is my bot server down?"
         request_retry(event, failure_message=failure_message)
+        return None
 
     except requests.exceptions.RequestException as e:
         response_message = (
@@ -336,3 +339,4 @@ def do_rest_call(base_url: str,
         logging.exception("Outhook trigger failed:", stack_info=True)
         fail_with_message(event, response_message)
         notify_bot_owner(event, exception=e)
+        return None

zerver/tests/test_decorators.py

@@ -1449,35 +1449,27 @@ class TestHumanUsersOnlyDecorator(ZulipTestCase):
 class TestAuthenticatedRequirePostDecorator(ZulipTestCase):
     def test_authenticated_html_post_view_with_get_request(self) -> None:
         self.login('hamlet')
-        with mock.patch('logging.warning') as mock_warning:
+        with self.assertLogs(level="WARNING") as mock_warning:
             result = self.client_get(r'/accounts/register/', {'stream': 'Verona'})
             self.assertEqual(result.status_code, 405)
-            mock_warning.assert_called_once()  # Check we logged the Mock Not Allowed
+            self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (GET): /accounts/register/"])
-            self.assertEqual(mock_warning.call_args_list[0][0],
-                             ('Method Not Allowed (%s): %s', 'GET', '/accounts/register/'))
 
-        with mock.patch('logging.warning') as mock_warning:
+        with self.assertLogs(level="WARNING") as mock_warning:
             result = self.client_get(r'/accounts/logout/', {'stream': 'Verona'})
             self.assertEqual(result.status_code, 405)
-            mock_warning.assert_called_once()  # Check we logged the Mock Not Allowed
+            self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (GET): /accounts/logout/"])
-            self.assertEqual(mock_warning.call_args_list[0][0],
-                             ('Method Not Allowed (%s): %s', 'GET', '/accounts/logout/'))
 
     def test_authenticated_json_post_view_with_get_request(self) -> None:
         self.login('hamlet')
-        with mock.patch('logging.warning') as mock_warning:
+        with self.assertLogs(level="WARNING") as mock_warning:
             result = self.client_get(r'/api/v1/dev_fetch_api_key', {'stream': 'Verona'})
             self.assertEqual(result.status_code, 405)
-            mock_warning.assert_called_once()  # Check we logged the Mock Not Allowed
+            self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (GET): /api/v1/dev_fetch_api_key"])
-            self.assertEqual(mock_warning.call_args_list[0][0],
-                             ('Method Not Allowed (%s): %s', 'GET', '/api/v1/dev_fetch_api_key'))
 
-        with mock.patch('logging.warning') as mock_warning:
+        with self.assertLogs(level="WARNING") as mock_warning:
             result = self.client_get(r'/json/remotes/server/register', {'stream': 'Verona'})
             self.assertEqual(result.status_code, 405)
-            mock_warning.assert_called_once()  # Check we logged the Mock Not Allowed
+            self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (GET): /json/remotes/server/register"])
-            self.assertEqual(mock_warning.call_args_list[0][0],
-                             ('Method Not Allowed (%s): %s', 'GET', '/json/remotes/server/register'))
 
 class TestAuthenticatedJsonPostViewDecorator(ZulipTestCase):
     def test_authenticated_json_post_view_if_everything_is_correct(self) -> None:

zerver/tests/test_email_log.py

@@ -11,7 +11,7 @@ class EmailLogTest(ZulipTestCase):
     def test_generate_and_clear_email_log(self) -> None:
         with self.settings(EMAIL_BACKEND='zproject.email_backends.EmailLogBackEnd'), \
                 mock.patch('zproject.email_backends.EmailLogBackEnd.send_email_smtp'), \
-                mock.patch('logging.info', return_value=None), \
+                self.assertLogs(level="INFO") as m, \
                 self.settings(DEVELOPMENT_LOG_EMAILS=True):
             result = self.client_get('/emails/generate/')
             self.assertEqual(result.status_code, 302)
@@ -24,6 +24,8 @@ class EmailLogTest(ZulipTestCase):
             self.assertEqual(result.status_code, 302)
             result = self.client_get(result['Location'])
             self.assertIn('manually generate most of the emails by clicking', str(result.content))
+            output_log = "INFO:root:Emails sent in development are available at http://testserver/emails"
+            self.assertEqual(m.output, [output_log for i in range(15)])
 
     def test_forward_address_details(self) -> None:
         forward_address = "forward-to@example.com"

zerver/tests/test_outgoing_webhook_system.py

@@ -75,10 +75,11 @@ class DoRestCallTests(ZulipTestCase):
         service_handler = GenericOutgoingWebhookService("token", bot_user, "service")
 
         response = ResponseMock(500)
+        with mock.patch('requests.request', return_value=response), self.assertLogs(level="WARNING") as m:
+            final_response = do_rest_call('',  None, mock_event, service_handler)
+            assert final_response is not None
 
-        with mock.patch('requests.request', return_value=response), mock.patch('logging.warning'):
+            self.assertEqual(m.output, [f"WARNING:root:Message http://zulip.testserver/#narrow/stream/999-Verona/topic/Foo/near/ triggered an outgoing webhook, returning status code 500.\n Content of response (in quotes): \"{final_response.content.decode()}\""])
-            do_rest_call('',  None, mock_event, service_handler)
-
         bot_owner_notification = self.get_last_message()
         self.assertEqual(bot_owner_notification.content,
                          '''[A message](http://zulip.testserver/#narrow/stream/999-Verona/topic/Foo/near/) triggered an outgoing webhook.
@@ -95,10 +96,12 @@ The webhook got a response with status code *500*.''')
         response = ResponseMock(400)
         expect_400 = mock.patch("requests.request", return_value=response)
         expect_fail = mock.patch("zerver.lib.outgoing_webhook.fail_with_message")
-        expect_warnings = mock.patch("logging.warning")
 
-        with expect_400, expect_fail as mock_fail, expect_warnings:
+        with expect_400, expect_fail as mock_fail, self.assertLogs(level="WARNING") as m:
-            do_rest_call('', None, mock_event, service_handler)
+            final_response = do_rest_call('', None, mock_event, service_handler)
+            assert final_response is not None
+
+            self.assertEqual(m.output, [f"WARNING:root:Message http://zulip.testserver/#narrow/stream/999-Verona/topic/Foo/near/ triggered an outgoing webhook, returning status code 400.\n Content of response (in quotes): \"{final_response.content.decode()}\""])
 
         self.assertTrue(mock_fail.called)
 
@@ -115,8 +118,11 @@ The webhook got a response with status code *400*.''')
         mock_event = self.mock_event(bot_user)
         service_handler = GenericOutgoingWebhookService("token", bot_user, "service")
 
-        with mock.patch('requests.request') as mock_request, mock.patch('logging.warning'):
+        with mock.patch('requests.request') as mock_request, self.assertLogs(level="WARNING") as m:
-            do_rest_call('', 'payload-stub', mock_event, service_handler)
+            final_response = do_rest_call('', 'payload-stub', mock_event, service_handler)
+            assert final_response is not None
+
+            self.assertEqual(m.output, [f"WARNING:root:Message http://zulip.testserver/#narrow/stream/999-Verona/topic/Foo/near/ triggered an outgoing webhook, returning status code {final_response.status_code}.\n Content of response (in quotes): \"{final_response.content.decode()}\""])
 
         kwargs = mock_request.call_args[1]
         self.assertEqual(kwargs['data'], 'payload-stub')
@@ -129,12 +135,13 @@ The webhook got a response with status code *400*.''')
         self.assertEqual(kwargs['headers'], headers)
 
     def test_error_handling(self) -> None:
-        def helper(side_effect: Any, error_text: str) -> None:
         bot_user = self.example_user('outgoing_webhook_bot')
         mock_event = self.mock_event(bot_user)
         service_handler = GenericOutgoingWebhookService("token", bot_user, "service")
+        bot_user_email = self.example_user_map['outgoing_webhook_bot']
+
+        def helper(side_effect: Any, error_text: str) -> None:
 
-            with mock.patch('logging.warning'), mock.patch('logging.info'):
             with mock.patch('requests.request', side_effect=side_effect):
                 do_rest_call('', None, mock_event, service_handler)
 
@@ -144,18 +151,30 @@ The webhook got a response with status code *400*.''')
             assert bot_user.bot_owner is not None
             self.assertEqual(bot_owner_notification.recipient_id, bot_user.bot_owner.id)
 
+        with self.assertLogs(level="INFO") as i:
             helper(side_effect=timeout_error, error_text='A timeout occurred.')
             helper(side_effect=connection_error, error_text='A connection error occurred.')
 
+            log_output = [
+                f"INFO:root:Trigger event {mock_event['command']} on {mock_event['service_name']} timed out. Retrying",
+                f"WARNING:root:Maximum retries exceeded for trigger:{bot_user_email} event:{mock_event['command']}",
+                f"INFO:root:Trigger event {mock_event['command']} on {mock_event['service_name']} resulted in a connection error. Retrying",
+                f"WARNING:root:Maximum retries exceeded for trigger:{bot_user_email} event:{mock_event['command']}"
+            ]
+
+            self.assertEqual(i.output, log_output)
+
     def test_request_exception(self) -> None:
         bot_user = self.example_user('outgoing_webhook_bot')
         mock_event = self.mock_event(bot_user)
         service_handler = GenericOutgoingWebhookService("token", bot_user, "service")
 
         expect_request_exception = mock.patch("requests.request", side_effect=request_exception_error)
-        expect_logging_exception = mock.patch("logging.exception")
+        expect_logging_exception = self.assertLogs(level="ERROR")
         expect_fail = mock.patch("zerver.lib.outgoing_webhook.fail_with_message")
 
+        # Don't think that we should catch and assert whole log output(which is actually a very big error traceback).
+        # We are already asserting bot_owner_notification.content which verifies exception did occur.
         with expect_request_exception, expect_logging_exception, expect_fail as mock_fail:
             do_rest_call('', None, mock_event, service_handler)
 

zerver/tests/test_push_notifications.py

@@ -869,6 +869,8 @@ class HandlePushNotificationTest(PushNotificationTest):
         # Now, delete the message the normal way
         do_delete_messages(user_profile.realm, [message])
 
+        # This mock.patch() should be assertNoLogs once that feature
+        # is added to Python.
         with mock.patch('zerver.lib.push_notifications.uses_notification_bouncer') as mock_check, \
                 mock.patch('logging.error') as mock_logging_error, \
                 mock.patch('zerver.lib.push_notifications.push_notifications_enabled', return_value = True) as mock_push_notifications:
@@ -1648,11 +1650,11 @@ class Result:
 
 class TestSendToPushBouncer(ZulipTestCase):
     @mock.patch('requests.request', return_value=Result(status=500))
-    @mock.patch('logging.warning')
+    def test_500_error(self, mock_request: mock.MagicMock) -> None:
-    def test_500_error(self, mock_request: mock.MagicMock, mock_warning: mock.MagicMock) -> None:
+        with self.assertLogs(level="WARNING") as m:
             with self.assertRaises(PushNotificationBouncerRetryLaterError):
-            result, failed = send_to_push_bouncer('register', 'register', {'data': 'true'})
+                send_to_push_bouncer('register', 'register', {'data': 'true'})
-        mock_warning.assert_called_once()
+            self.assertEqual(m.output, ["WARNING:root:Received 500 from push notification bouncer"])
 
     @mock.patch('requests.request', return_value=Result(status=400))
     def test_400_error(self, mock_request: mock.MagicMock) -> None:

zerver/tests/test_realm.py

@@ -853,7 +853,7 @@ class ScrubRealmTest(ZulipTestCase):
 
         self.assertNotEqual(CustomProfileField.objects.filter(realm=zulip).count(), 0)
 
-        with mock.patch('logging.warning'):
+        with self.assertLogs(level="WARNING"):
             do_scrub_realm(zulip)
 
         self.assertEqual(Message.objects.filter(sender__in=[iago, othello]).count(), 0)