From c6a5c8ef10cbcb90512235b0bdc5d05e9acc45b2 Mon Sep 17 00:00:00 2001 From: Joey Orlando Date: Fri, 9 Aug 2024 10:51:20 -0400 Subject: [PATCH] add better logging for Google Calendar task (#4792) # What this PR does Attempting to solve some Celery retry errors we're seeing around `apps.google.tasks.sync_out_of_office_calendar_events_for_user`. This PR adds better logging and documents some findings so far. ## Checklist - [x] Unit, integration, and e2e (if applicable) tests updated - [x] Documentation added (or `pr:no public docs` PR label added if not required) - [x] Added the relevant release notes label (see labels prefixed w/ `release:`). These labels dictate how your PR will show up in the autogenerated release notes. --- engine/apps/google/client.py | 40 +++++++++++++++++-- engine/apps/google/tasks.py | 19 +++++++-- ..._out_of_office_calendar_events_for_user.py | 2 +- engine/apps/social_auth/pipeline/google.py | 4 +- engine/apps/user_management/models/user.py | 14 +++++-- .../apps/user_management/tests/test_user.py | 12 +++--- engine/pyproject.toml | 1 + 7 files changed, 74 insertions(+), 18 deletions(-) diff --git a/engine/apps/google/client.py b/engine/apps/google/client.py index a0544ab3..bf7f9818 100644 --- a/engine/apps/google/client.py +++ b/engine/apps/google/client.py @@ -3,6 +3,7 @@ import logging import typing from django.conf import settings +from google.auth.exceptions import RefreshError from google.oauth2.credentials import Credentials from googleapiclient.discovery import build from googleapiclient.errors import HttpError @@ -24,11 +25,24 @@ class GoogleCalendarEvent: self.end_time_utc = self._end_time.astimezone(datetime.timezone.utc) -class GoogleCalendarHTTPError(Exception): +class _GoogleCalendarHTTPError(Exception): def __init__(self, http_error) -> None: self.error = http_error +class GoogleCalendarGenericHTTPError(_GoogleCalendarHTTPError): + """Raised when a generic HTTP error occurs when communicating with the Google Calendar API""" + + +class GoogleCalendarUnauthorizedHTTPError(_GoogleCalendarHTTPError): + """Raised when an HTTP 403 error occurs when communicating with the Google Calendar API""" + + +class GoogleCalendarRefreshError(Exception): + def __init__(self, refresh_error) -> None: + self.error = refresh_error + + class GoogleCalendarAPIClient: MAX_NUMBER_OF_CALENDAR_EVENTS_TO_FETCH = 250 """ @@ -89,7 +103,27 @@ class GoogleCalendarAPIClient: .execute() ) except HttpError as e: - logger.error(f"GoogleCalendarAPIClient - Error fetching out of office events: {e}") - raise GoogleCalendarHTTPError(e) + if e.status_code == 403: + # this scenario can be encountered when, for some reason, the OAuth2 token that we have + # does not contain the https://www.googleapis.com/auth/calendar.events.readonly scope + # example error: + # # noqa: E501 + logger.error(f"GoogleCalendarAPIClient - HttpError 403 when fetching out of office events: {e}") + raise GoogleCalendarUnauthorizedHTTPError(e) + + logger.error(f"GoogleCalendarAPIClient - HttpError when fetching out of office events: {e}") + raise GoogleCalendarGenericHTTPError(e) + except RefreshError as e: + # TODO: come back and solve this properly once we get better logging output + # it seems like right now we are seeing RefreshError in two different scenarios: + # 1. RefreshError('invalid_grant: Account has been deleted', {'error': 'invalid_grant', 'error_description': 'Account has been deleted'}) + # 2. RefreshError('invalid_grant: Token has been expired or revoked.', {'error': 'invalid_grant', 'error_description': 'Token has been expired or revoked.'}) + # https://stackoverflow.com/a/49024030/3902555 + logger.error( + f"GoogleCalendarAPIClient - RefreshError when fetching out of office events: {e} " + # NOTE: remove e.args after debugging how to dig into the error details + f"args={e.args}" + ) + raise GoogleCalendarRefreshError(e) return [GoogleCalendarEvent(event) for event in events_result.get("items", [])] diff --git a/engine/apps/google/tasks.py b/engine/apps/google/tasks.py index 77b3d967..a1fa7ac5 100644 --- a/engine/apps/google/tasks.py +++ b/engine/apps/google/tasks.py @@ -3,7 +3,12 @@ import logging from celery.utils.log import get_task_logger from apps.google import constants -from apps.google.client import GoogleCalendarAPIClient, GoogleCalendarHTTPError +from apps.google.client import ( + GoogleCalendarAPIClient, + GoogleCalendarGenericHTTPError, + GoogleCalendarRefreshError, + GoogleCalendarUnauthorizedHTTPError, +) from apps.google.models import GoogleOAuth2User from apps.schedules.models import OnCallSchedule, ShiftSwapRequest from common.custom_celery_tasks import shared_dedicated_queue_retry_task @@ -33,8 +38,16 @@ def sync_out_of_office_calendar_events_for_user(google_oauth2_user_pk: int) -> N try: out_of_office_events = google_api_client.fetch_out_of_office_events() - except GoogleCalendarHTTPError: - logger.info(f"Failed to fetch out of office events for user {user_id}") + except GoogleCalendarUnauthorizedHTTPError: + # this happens because the user's access token is (somehow) missing the + # https://www.googleapis.com/auth/calendar.events.readonly scope + # they will need to reconnect their Google account and grant us the necessary scopes, retrying will not help + logger.exception(f"Failed to fetch out of office events for user {user_id} due to an unauthorized HTTP error") + # TODO: come back and solve this properly once we get better logging output + # user.reset_google_oauth2_settings() + return + except (GoogleCalendarRefreshError, GoogleCalendarGenericHTTPError): + logger.exception(f"Failed to fetch out of office events for user {user_id}") return for out_of_office_event in out_of_office_events: diff --git a/engine/apps/google/tests/test_sync_out_of_office_calendar_events_for_user.py b/engine/apps/google/tests/test_sync_out_of_office_calendar_events_for_user.py index 69f1020b..4ba50de2 100644 --- a/engine/apps/google/tests/test_sync_out_of_office_calendar_events_for_user.py +++ b/engine/apps/google/tests/test_sync_out_of_office_calendar_events_for_user.py @@ -125,7 +125,7 @@ def test_setup( user_name = "Bob Smith" user = make_user_for_organization( organization, - # normally this 👇 is done via User.finish_google_oauth2_connection_flow.. but since we're creating + # normally this 👇 is done via User.save_google_oauth2_settings.. but since we're creating # the user via a fixture we need to manually add this google_calendar_settings={ "oncall_schedules_to_consider_for_shift_swaps": [], diff --git a/engine/apps/social_auth/pipeline/google.py b/engine/apps/social_auth/pipeline/google.py index 37702b39..bed5996b 100644 --- a/engine/apps/social_auth/pipeline/google.py +++ b/engine/apps/social_auth/pipeline/google.py @@ -19,7 +19,7 @@ def persist_access_and_refresh_tokens(backend: typing.Type[BaseAuth], response: https://medium.com/starthinker/google-oauth-2-0-access-token-and-refresh-token-explained-cccf2fc0a6d9 """ - user.finish_google_oauth2_connection_flow(response) + user.save_google_oauth2_settings(response) def disconnect_user_google_oauth2_settings(backend: typing.Type[BaseAuth], user: User, *args, **kwargs): @@ -58,6 +58,6 @@ def disconnect_user_google_oauth2_settings(backend: typing.Type[BaseAuth], user: else: logger.info(f"Google OAuth2 token for user {user_pk} is already invalid or revoked, ignoring error") - user.finish_google_oauth2_disconnection_flow() + user.reset_google_oauth2_settings() logger.info(f"Successfully disconnected user {user.pk} from Google OAuth2") diff --git a/engine/apps/user_management/models/user.py b/engine/apps/user_management/models/user.py index 1e459207..97163883 100644 --- a/engine/apps/user_management/models/user.py +++ b/engine/apps/user_management/models/user.py @@ -382,8 +382,14 @@ class User(models.Model): self.alert_group_table_selected_columns = columns self.save(update_fields=["alert_group_table_selected_columns"]) - def finish_google_oauth2_connection_flow(self, google_oauth2_response: "GoogleOauth2Response") -> None: - _obj, created = GoogleOAuth2User.objects.update_or_create( + def save_google_oauth2_settings(self, google_oauth2_response: "GoogleOauth2Response") -> None: + logger.info( + f"Saving Google OAuth2 settings for user {self.pk} " + f"sub={google_oauth2_response.get('sub')} " + f"oauth_scope={google_oauth2_response.get('oauth_scope')}" + ) + + _, created = GoogleOAuth2User.objects.update_or_create( user=self, defaults={ "google_user_id": google_oauth2_response.get("sub"), @@ -398,7 +404,9 @@ class User(models.Model): } self.save(update_fields=["google_calendar_settings"]) - def finish_google_oauth2_disconnection_flow(self) -> None: + def reset_google_oauth2_settings(self) -> None: + logger.info(f"Resetting Google OAuth2 settings for user {self.pk}") + GoogleOAuth2User.objects.filter(user=self).delete() self.google_calendar_settings = None diff --git a/engine/apps/user_management/tests/test_user.py b/engine/apps/user_management/tests/test_user.py index 7dc8a384..54e95788 100644 --- a/engine/apps/user_management/tests/test_user.py +++ b/engine/apps/user_management/tests/test_user.py @@ -121,7 +121,7 @@ def test_has_google_oauth2_connected(make_organization_and_user, make_google_oau @pytest.mark.django_db -def test_finish_google_oauth2_connection_flow(make_organization_and_user): +def test_save_google_oauth2_settings(make_organization_and_user): oauth_response = { "access_token": "access", "refresh_token": "refresh", @@ -134,7 +134,7 @@ def test_finish_google_oauth2_connection_flow(make_organization_and_user): assert GoogleOAuth2User.objects.filter(user=user).exists() is False assert user.google_calendar_settings is None - user.finish_google_oauth2_connection_flow(oauth_response) + user.save_google_oauth2_settings(oauth_response) user.refresh_from_db() google_oauth_user = user.google_oauth2_user @@ -151,7 +151,7 @@ def test_finish_google_oauth2_connection_flow(make_organization_and_user): "scope": "scope2", } - user.finish_google_oauth2_connection_flow(oauth_response2) + user.save_google_oauth2_settings(oauth_response2) user.refresh_from_db() google_oauth_user = user.google_oauth2_user @@ -162,10 +162,10 @@ def test_finish_google_oauth2_connection_flow(make_organization_and_user): @pytest.mark.django_db -def test_finish_google_oauth2_disconnection_flow(make_organization_and_user): +def test_reset_google_oauth2_settings(make_organization_and_user): _, user = make_organization_and_user() - user.finish_google_oauth2_connection_flow( + user.save_google_oauth2_settings( { "access_token": "access", "refresh_token": "refresh", @@ -178,7 +178,7 @@ def test_finish_google_oauth2_disconnection_flow(make_organization_and_user): assert user.google_oauth2_user is not None assert user.google_calendar_settings is not None - user.finish_google_oauth2_disconnection_flow() + user.reset_google_oauth2_settings() user.refresh_from_db() assert GoogleOAuth2User.objects.filter(user=user).exists() is False diff --git a/engine/pyproject.toml b/engine/pyproject.toml index a1bab7d7..e6708a8e 100644 --- a/engine/pyproject.toml +++ b/engine/pyproject.toml @@ -57,6 +57,7 @@ module = [ "factory.*", "fcm_django.*", "firebase_admin.*", + "google.auth.exceptions.*", "googleapiclient.discovery.*", "googleapiclient.errors.*", "google.oauth2.credentials.*",