From cbfd6464a559217382c0e7eb1bf3fdd0d25acfbf Mon Sep 17 00:00:00 2001 From: m-e-l-u-h-a-n Date: Fri, 30 Oct 2020 00:51:18 +0530 Subject: [PATCH] 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 | 19 ++++--- zerver/lib/outgoing_webhook.py | 8 ++- zerver/tests/test_decorators.py | 24 +++------ zerver/tests/test_email_log.py | 4 +- zerver/tests/test_outgoing_webhook_system.py | 55 +++++++++++++------- zerver/tests/test_push_notifications.py | 12 +++-- zerver/tests/test_realm.py | 2 +- 7 files changed, 75 insertions(+), 49 deletions(-) diff --git a/analytics/tests/test_views.py b/analytics/tests/test_views.py index ca12eb8381..a9b5df167c 100644 --- a/analytics/tests/test_views.py +++ b/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'): - result = self.client_get('/json/analytics/chart_data', - {'chart_name': 'messages_sent_over_time'}) + 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, 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) diff --git a/zerver/lib/outgoing_webhook.py b/zerver/lib/outgoing_webhook.py index 5c745e56a4..379ce727ad 100644 --- a/zerver/lib/outgoing_webhook.py +++ b/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 diff --git a/zerver/tests/test_decorators.py b/zerver/tests/test_decorators.py index 6f61ce23f3..9c69a597b6 100644 --- a/zerver/tests/test_decorators.py +++ b/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.call_args_list[0][0], - ('Method Not Allowed (%s): %s', 'GET', '/accounts/register/')) + self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (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.call_args_list[0][0], - ('Method Not Allowed (%s): %s', 'GET', '/accounts/logout/')) + self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (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.call_args_list[0][0], - ('Method Not Allowed (%s): %s', 'GET', '/api/v1/dev_fetch_api_key')) + self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (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.call_args_list[0][0], - ('Method Not Allowed (%s): %s', 'GET', '/json/remotes/server/register')) + self.assertEqual(mock_warning.output, ["WARNING:root:Method Not Allowed (GET): /json/remotes/server/register"]) class TestAuthenticatedJsonPostViewDecorator(ZulipTestCase): def test_authenticated_json_post_view_if_everything_is_correct(self) -> None: diff --git a/zerver/tests/test_email_log.py b/zerver/tests/test_email_log.py index ee90bbc9d1..b908998876 100644 --- a/zerver/tests/test_email_log.py +++ b/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" diff --git a/zerver/tests/test_outgoing_webhook_system.py b/zerver/tests/test_outgoing_webhook_system.py index 19886e0983..1cae7b75c5 100644 --- a/zerver/tests/test_outgoing_webhook_system.py +++ b/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'): - do_rest_call('', None, mock_event, service_handler) - + 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()}\""]) 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: - do_rest_call('', None, mock_event, service_handler) + with expect_400, expect_fail as mock_fail, self.assertLogs(level="WARNING") as m: + 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'): - do_rest_call('', 'payload-stub', mock_event, service_handler) + with mock.patch('requests.request') as mock_request, self.assertLogs(level="WARNING") as m: + 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,14 +135,15 @@ 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 = 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'] - 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) + def helper(side_effect: Any, error_text: str) -> None: + + with mock.patch('requests.request', side_effect=side_effect): + do_rest_call('', None, mock_event, service_handler) bot_owner_notification = self.get_last_message() self.assertIn(error_text, bot_owner_notification.content) @@ -144,8 +151,18 @@ 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) - helper(side_effect=timeout_error, error_text='A timeout occurred.') - helper(side_effect=connection_error, error_text='A connection error occurred.') + 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') @@ -153,9 +170,11 @@ The webhook got a response with status code *400*.''') 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) diff --git a/zerver/tests/test_push_notifications.py b/zerver/tests/test_push_notifications.py index dcd92139d3..8584391e6a 100644 --- a/zerver/tests/test_push_notifications.py +++ b/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, mock_warning: mock.MagicMock) -> None: - with self.assertRaises(PushNotificationBouncerRetryLaterError): - result, failed = send_to_push_bouncer('register', 'register', {'data': 'true'}) - mock_warning.assert_called_once() + def test_500_error(self, mock_request: mock.MagicMock) -> None: + with self.assertLogs(level="WARNING") as m: + with self.assertRaises(PushNotificationBouncerRetryLaterError): + send_to_push_bouncer('register', 'register', {'data': 'true'}) + 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: diff --git a/zerver/tests/test_realm.py b/zerver/tests/test_realm.py index f691b8e33d..e07402ac89 100644 --- a/zerver/tests/test_realm.py +++ b/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)