-
Notifications
You must be signed in to change notification settings - Fork 1.7k
fix(auth): lower regional access boundary logs from warning to debug. #17571
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -219,10 +219,9 @@ def start_blocking_refresh(self, credentials, request): | |
| """ | ||
| # Async credentials do not support blocking lookups. | ||
| if inspect.iscoroutinefunction(credentials._lookup_regional_access_boundary): | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| _LOGGER.warning( | ||
| "Blocking Regional Access Boundary lookup is not supported for async credentials." | ||
| ) | ||
| _LOGGER.debug( | ||
| "Blocking Regional Access Boundary lookup is not supported for async credentials." | ||
| ) | ||
| self.process_regional_access_boundary_info(None) | ||
| return | ||
|
|
||
|
|
@@ -234,12 +233,11 @@ def start_blocking_refresh(self, credentials, request): | |
| credentials._lookup_regional_access_boundary(request, fail_fast=True) | ||
| ) | ||
| except Exception as e: | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| _LOGGER.warning( | ||
| "Blocking Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| _LOGGER.debug( | ||
| "Blocking Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| regional_access_boundary_info = None | ||
|
|
||
| self.process_regional_access_boundary_info(regional_access_boundary_info) | ||
|
|
@@ -265,12 +263,11 @@ async def start_blocking_refresh_async(self, credentials, request): | |
| ) | ||
| ) | ||
| except Exception as e: | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| _LOGGER.warning( | ||
| "Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| _LOGGER.debug( | ||
| "Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| regional_access_boundary_info = None | ||
|
|
||
| self.process_regional_access_boundary_info(regional_access_boundary_info) | ||
|
|
@@ -297,14 +294,12 @@ def process_regional_access_boundary_info(self, regional_access_boundary_info): | |
| cooldown_expiry=None, | ||
| cooldown_duration=DEFAULT_REGIONAL_ACCESS_BOUNDARY_COOLDOWN, | ||
| ) | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| _LOGGER.debug("Regional Access Boundary lookup successful.") | ||
| _LOGGER.debug("Regional Access Boundary lookup successful.") | ||
| else: | ||
| # On failure, calculate cooldown and update state. | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| _LOGGER.warning( | ||
| "Regional Access Boundary lookup failed. Entering cooldown." | ||
| ) | ||
| _LOGGER.debug( | ||
| "Regional Access Boundary lookup failed. Entering cooldown." | ||
| ) | ||
|
|
||
| next_cooldown_expiry = ( | ||
| _helpers.utcnow() + current_data.cooldown_duration | ||
|
|
@@ -367,12 +362,11 @@ def run(self): | |
| self._credentials._lookup_regional_access_boundary(self._request) | ||
| ) | ||
| except Exception as e: | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| _LOGGER.warning( | ||
| "Asynchronous Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| _LOGGER.debug( | ||
| "Asynchronous Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| regional_access_boundary_info = None | ||
|
|
||
| self._rab_manager.process_regional_access_boundary_info( | ||
|
|
@@ -419,13 +413,12 @@ def start_refresh(self, credentials, request, rab_manager): | |
| try: | ||
| copied_request = copy.deepcopy(request) | ||
| except Exception as e: | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| _LOGGER.warning( | ||
| "Could not deepcopy transport for background RAB refresh. " | ||
| "Skipping background refresh to avoid thread safety issues. " | ||
| "Exception: %s", | ||
| e, | ||
| ) | ||
| _LOGGER.debug( | ||
| "Could not deepcopy transport for background RAB refresh. " | ||
| "Skipping background refresh to avoid thread safety issues. " | ||
| "Exception: %s", | ||
| e, | ||
| ) | ||
| return | ||
|
|
||
| self._worker = _RegionalAccessBoundaryRefreshThread( | ||
|
|
@@ -479,14 +472,13 @@ async def _close_cloned_request(lookup_request, is_cloned): | |
| if is_async := inspect.isawaitable(maybe_coro): | ||
| await maybe_coro | ||
| except Exception as e: | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
| adapter_type = " asynchronous " if is_async else " " | ||
| _LOGGER.warning( | ||
| "Failed to cleanly close cloned%srequest transport: %s", | ||
| adapter_type, | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| adapter_type = " asynchronous " if is_async else " " | ||
| _LOGGER.debug( | ||
| "Failed to cleanly close cloned%srequest transport: %s", | ||
| adapter_type, | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
|
|
||
|
|
||
| class _AsyncRegionalAccessBoundaryRefreshManager(object): | ||
|
|
@@ -532,12 +524,11 @@ def start_refresh(self, credentials, request, rab_manager): | |
| is_cloned, | ||
| ) = _prepare_async_lookup_callable(request) | ||
| except Exception as e: | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Ditto on the removal of this check |
||
| _LOGGER.warning( | ||
| "Synchronous cloning of request for Regional Access Boundary lookup failed: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| _LOGGER.debug( | ||
| "Synchronous cloning of request for Regional Access Boundary lookup failed: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| rab_manager.process_regional_access_boundary_info(None) | ||
| return | ||
|
|
||
|
|
@@ -549,12 +540,11 @@ async def _worker(): | |
| ) | ||
| ) | ||
| except Exception as e: | ||
| if _helpers.is_logging_enabled(_LOGGER): | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Ditto |
||
| _LOGGER.warning( | ||
| "Asynchronous Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| _LOGGER.debug( | ||
| "Asynchronous Regional Access Boundary lookup raised an exception: %s", | ||
| e, | ||
| exc_info=True, | ||
| ) | ||
| regional_access_boundary_info = None | ||
| finally: | ||
| await _close_cloned_request(lookup_request, is_cloned) | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -13,6 +13,7 @@ | |
| # limitations under the License. | ||
|
|
||
| import datetime | ||
| import logging | ||
| from unittest import mock | ||
|
|
||
| import pytest # type: ignore | ||
|
|
@@ -24,6 +25,23 @@ | |
| from google.oauth2 import credentials as oauth2_credentials | ||
|
|
||
|
|
||
| @pytest.fixture | ||
| def rab_caplog(caplog): | ||
| """Fixture to configure logging capture and ensure propagation for RAB utilities.""" | ||
|
|
||
| caplog.set_level( | ||
| logging.DEBUG, logger="google.auth._regional_access_boundary_utils" | ||
| ) | ||
|
|
||
| google_logger = logging.getLogger("google") | ||
| original_propagate = google_logger.propagate | ||
| google_logger.propagate = True | ||
| try: | ||
| yield caplog | ||
| finally: | ||
| google_logger.propagate = original_propagate | ||
|
|
||
|
|
||
| class CredentialsImpl(credentials.CredentialsWithRegionalAccessBoundary): | ||
| def __init__(self, universe_domain=None): | ||
| super(CredentialsImpl, self).__init__() | ||
|
|
@@ -379,7 +397,7 @@ def test_lookup_regional_access_boundary_success(self, mock_lookup_rab): | |
| assert rab_manager._data.cooldown_expiry is None | ||
|
|
||
| @mock.patch.object(CredentialsImpl, "_lookup_regional_access_boundary") | ||
| def test_lookup_regional_access_boundary_failure(self, mock_lookup_rab): | ||
| def test_lookup_regional_access_boundary_failure(self, mock_lookup_rab, rab_caplog): | ||
| creds = CredentialsImpl() | ||
| request = mock.Mock() | ||
| rab_manager = _regional_access_boundary_utils._RegionalAccessBoundaryManager() | ||
|
|
@@ -396,6 +414,14 @@ def test_lookup_regional_access_boundary_failure(self, mock_lookup_rab): | |
| assert rab_manager._data.expiry is None | ||
| assert rab_manager._data.cooldown_expiry is not None | ||
|
|
||
| assert ( | ||
| "Regional Access Boundary lookup failed. Entering cooldown." | ||
| in rab_caplog.text | ||
| ) | ||
| # RAB failures should be logged at INFO level. | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. INFO level comment is now obsolete it seems |
||
| warning_logs = [t for t in rab_caplog.record_tuples if t[1] == logging.WARNING] | ||
| assert not warning_logs, f"Unexpected warnings emitted: {warning_logs}" | ||
|
|
||
| def test_lookup_regional_access_boundary_null_url(self): | ||
| creds = oauth2_credentials.Credentials(token="token") | ||
| request = mock.Mock() | ||
|
|
@@ -441,7 +467,9 @@ def test_regional_access_boundary_refresh_thread_run_success(self, mock_utcnow): | |
| assert rab_manager._data.cooldown_expiry is None | ||
|
|
||
| @mock.patch("google.auth._helpers.utcnow") | ||
| def test_regional_access_boundary_refresh_thread_run_failure(self, mock_utcnow): | ||
| def test_regional_access_boundary_refresh_thread_run_failure( | ||
| self, mock_utcnow, rab_caplog | ||
| ): | ||
| mock_now = datetime.datetime(2025, 1, 1, 12, 0, 0) | ||
| mock_utcnow.return_value = mock_now | ||
|
|
||
|
|
@@ -466,6 +494,18 @@ def test_regional_access_boundary_refresh_thread_run_failure(self, mock_utcnow): | |
| assert rab_manager._data.cooldown_expiry == expected_cooldown_expiry | ||
| assert rab_manager._data.cooldown_duration == initial_cooldown * 2 | ||
|
|
||
| assert ( | ||
| "Asynchronous Regional Access Boundary lookup raised an exception" | ||
| in rab_caplog.text | ||
| ) | ||
| assert ( | ||
| "Regional Access Boundary lookup failed. Entering cooldown." | ||
| in rab_caplog.text | ||
| ) | ||
| # RAB failures should be logged at INFO level. | ||
| warning_logs = [t for t in rab_caplog.record_tuples if t[1] == logging.WARNING] | ||
| assert not warning_logs, f"Unexpected warnings emitted: {warning_logs}" | ||
|
|
||
| @mock.patch("google.auth._helpers.utcnow") | ||
| def test_regional_access_boundary_refresh_thread_run_failure_hard_expiry( | ||
| self, mock_utcnow | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why did we get rid of the is_logging_enabled check here? Was that intentional?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes it was intentional. Previously, these were logged a WARNING. Because warnings are printed by default, we had to manually wrap it in that if check (which checks for DEBUG level) to hide it from normal users.
Now that we are logging them as _LOGGER.debug, they are already hidden by default. The logging library automatically filters out DEBUG logs, so we no longer need to write a manual if check to hide them.