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.
This commit is contained in:
Joey Orlando 2024-08-09 10:51:20 -04:00 committed by GitHub
parent 93c92a7a4c
commit c6a5c8ef10
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
7 changed files with 74 additions and 18 deletions

View file

@ -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:
# <HttpError 403 when requesting https://www.googleapis.com/calendar/v3/calendars/primary/events?timeMin=2024-08-08T14%3A00%3A00%2B0000&timeMax=2024-09-07T14%3A00%3A00%2B0000&maxResults=250&singleEvents=true&orderBy=startTime&eventTypes=outOfOffice&alt=json returned "Request had insufficient authentication scopes.". Details: "[{'message': 'Insufficient Permission', 'domain': 'global', 'reason': 'insufficientPermissions'}]"> # 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", [])]

View file

@ -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:

View file

@ -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": [],

View file

@ -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")

View file

@ -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

View file

@ -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

View file

@ -57,6 +57,7 @@ module = [
"factory.*",
"fcm_django.*",
"firebase_admin.*",
"google.auth.exceptions.*",
"googleapiclient.discovery.*",
"googleapiclient.errors.*",
"google.oauth2.credentials.*",