Skip to content

Commit 1ef4183

Browse files
nbayatinbayati
authored
fix(auth): lower regional access boundary logs from warning to debug. (#17571)
When the library tries to look up Regional Access Boundaries in the background and fails, it used to print a "WARNING" message. Because these lookups are optional and failing is not considered fatal or blocking, omitting warnings creates a lot of log noise for the users. This change lowers those messages to the "DEBUG" level so they stay out of the way by default. fixes #17515
1 parent bd782cf commit 1ef4183

7 files changed

Lines changed: 96 additions & 103 deletions

File tree

‎packages/google-auth/google/auth/_regional_access_boundary_utils.py‎

Lines changed: 45 additions & 55 deletions
Original file line numberDiff line numberDiff line change
@@ -219,10 +219,9 @@ def start_blocking_refresh(self, credentials, request):
219219
"""
220220
# Async credentials do not support blocking lookups.
221221
if inspect.iscoroutinefunction(credentials._lookup_regional_access_boundary):
222-
if _helpers.is_logging_enabled(_LOGGER):
223-
_LOGGER.warning(
224-
"Blocking Regional Access Boundary lookup is not supported for async credentials."
225-
)
222+
_LOGGER.debug(
223+
"Blocking Regional Access Boundary lookup is not supported for async credentials."
224+
)
226225
self.process_regional_access_boundary_info(None)
227226
return
228227

@@ -234,12 +233,11 @@ def start_blocking_refresh(self, credentials, request):
234233
credentials._lookup_regional_access_boundary(request, fail_fast=True)
235234
)
236235
except Exception as e:
237-
if _helpers.is_logging_enabled(_LOGGER):
238-
_LOGGER.warning(
239-
"Blocking Regional Access Boundary lookup raised an exception: %s",
240-
e,
241-
exc_info=True,
242-
)
236+
_LOGGER.debug(
237+
"Blocking Regional Access Boundary lookup raised an exception: %s",
238+
e,
239+
exc_info=True,
240+
)
243241
regional_access_boundary_info = None
244242

245243
self.process_regional_access_boundary_info(regional_access_boundary_info)
@@ -265,12 +263,11 @@ async def start_blocking_refresh_async(self, credentials, request):
265263
)
266264
)
267265
except Exception as e:
268-
if _helpers.is_logging_enabled(_LOGGER):
269-
_LOGGER.warning(
270-
"Regional Access Boundary lookup raised an exception: %s",
271-
e,
272-
exc_info=True,
273-
)
266+
_LOGGER.debug(
267+
"Regional Access Boundary lookup raised an exception: %s",
268+
e,
269+
exc_info=True,
270+
)
274271
regional_access_boundary_info = None
275272

276273
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):
297294
cooldown_expiry=None,
298295
cooldown_duration=DEFAULT_REGIONAL_ACCESS_BOUNDARY_COOLDOWN,
299296
)
300-
if _helpers.is_logging_enabled(_LOGGER):
301-
_LOGGER.debug("Regional Access Boundary lookup successful.")
297+
_LOGGER.debug("Regional Access Boundary lookup successful.")
302298
else:
303299
# On failure, calculate cooldown and update state.
304-
if _helpers.is_logging_enabled(_LOGGER):
305-
_LOGGER.warning(
306-
"Regional Access Boundary lookup failed. Entering cooldown."
307-
)
300+
_LOGGER.debug(
301+
"Regional Access Boundary lookup failed. Entering cooldown."
302+
)
308303

309304
next_cooldown_expiry = (
310305
_helpers.utcnow() + current_data.cooldown_duration
@@ -367,12 +362,11 @@ def run(self):
367362
self._credentials._lookup_regional_access_boundary(self._request)
368363
)
369364
except Exception as e:
370-
if _helpers.is_logging_enabled(_LOGGER):
371-
_LOGGER.warning(
372-
"Asynchronous Regional Access Boundary lookup raised an exception: %s",
373-
e,
374-
exc_info=True,
375-
)
365+
_LOGGER.debug(
366+
"Asynchronous Regional Access Boundary lookup raised an exception: %s",
367+
e,
368+
exc_info=True,
369+
)
376370
regional_access_boundary_info = None
377371

378372
self._rab_manager.process_regional_access_boundary_info(
@@ -419,13 +413,12 @@ def start_refresh(self, credentials, request, rab_manager):
419413
try:
420414
copied_request = copy.deepcopy(request)
421415
except Exception as e:
422-
if _helpers.is_logging_enabled(_LOGGER):
423-
_LOGGER.warning(
424-
"Could not deepcopy transport for background RAB refresh. "
425-
"Skipping background refresh to avoid thread safety issues. "
426-
"Exception: %s",
427-
e,
428-
)
416+
_LOGGER.debug(
417+
"Could not deepcopy transport for background RAB refresh. "
418+
"Skipping background refresh to avoid thread safety issues. "
419+
"Exception: %s",
420+
e,
421+
)
429422
return
430423

431424
self._worker = _RegionalAccessBoundaryRefreshThread(
@@ -479,14 +472,13 @@ async def _close_cloned_request(lookup_request, is_cloned):
479472
if is_async := inspect.isawaitable(maybe_coro):
480473
await maybe_coro
481474
except Exception as e:
482-
if _helpers.is_logging_enabled(_LOGGER):
483-
adapter_type = " asynchronous " if is_async else " "
484-
_LOGGER.warning(
485-
"Failed to cleanly close cloned%srequest transport: %s",
486-
adapter_type,
487-
e,
488-
exc_info=True,
489-
)
475+
adapter_type = " asynchronous " if is_async else " "
476+
_LOGGER.debug(
477+
"Failed to cleanly close cloned%srequest transport: %s",
478+
adapter_type,
479+
e,
480+
exc_info=True,
481+
)
490482

491483

492484
class _AsyncRegionalAccessBoundaryRefreshManager(object):
@@ -532,12 +524,11 @@ def start_refresh(self, credentials, request, rab_manager):
532524
is_cloned,
533525
) = _prepare_async_lookup_callable(request)
534526
except Exception as e:
535-
if _helpers.is_logging_enabled(_LOGGER):
536-
_LOGGER.warning(
537-
"Synchronous cloning of request for Regional Access Boundary lookup failed: %s",
538-
e,
539-
exc_info=True,
540-
)
527+
_LOGGER.debug(
528+
"Synchronous cloning of request for Regional Access Boundary lookup failed: %s",
529+
e,
530+
exc_info=True,
531+
)
541532
rab_manager.process_regional_access_boundary_info(None)
542533
return
543534

@@ -549,12 +540,11 @@ async def _worker():
549540
)
550541
)
551542
except Exception as e:
552-
if _helpers.is_logging_enabled(_LOGGER):
553-
_LOGGER.warning(
554-
"Asynchronous Regional Access Boundary lookup raised an exception: %s",
555-
e,
556-
exc_info=True,
557-
)
543+
_LOGGER.debug(
544+
"Asynchronous Regional Access Boundary lookup raised an exception: %s",
545+
e,
546+
exc_info=True,
547+
)
558548
regional_access_boundary_info = None
559549
finally:
560550
await _close_cloned_request(lookup_request, is_cloned)

‎packages/google-auth/google/auth/compute_engine/credentials.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -219,7 +219,7 @@ def _build_regional_access_boundary_lookup_url(
219219
return None
220220

221221
if not _metadata._is_service_account_email(self.service_account_email):
222-
_LOGGER.info(
222+
_LOGGER.debug(
223223
"Service account email '%s' is not a valid email. Skipping Regional Access Boundary lookup.",
224224
self.service_account_email,
225225
)

‎packages/google-auth/google/auth/credentials.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -535,7 +535,7 @@ def _lookup_regional_access_boundary(
535535

536536
url = self._build_regional_access_boundary_lookup_url(request=request)
537537
if not url:
538-
_LOGGER.warning("Failed to build Regional Access Boundary lookup URL.")
538+
_LOGGER.debug("Failed to build Regional Access Boundary lookup URL.")
539539
return None
540540

541541
headers: Dict[str, str] = {}

‎packages/google-auth/google/oauth2/_client.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -582,7 +582,7 @@ def _lookup_regional_access_boundary_request(
582582
request, url, can_retry=can_retry, headers=headers, fail_fast=fail_fast
583583
)
584584
if not response_status_ok:
585-
_LOGGER.warning(
585+
_LOGGER.debug(
586586
"Regional Access Boundary HTTP request failed after retries: response_data=%s, retryable_error=%s",
587587
response_data,
588588
retryable_error,

‎packages/google-auth/google/oauth2/_client_async.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -356,7 +356,7 @@ async def _lookup_regional_access_boundary_request(
356356
request, url, can_retry=can_retry, headers=headers, fail_fast=fail_fast
357357
)
358358
if not response_status_ok:
359-
client._LOGGER.warning(
359+
client._LOGGER.debug(
360360
"Regional Access Boundary HTTP request failed after retries: response_data=%s, retryable_error=%s",
361361
response_data,
362362
retryable_error,

‎packages/google-auth/tests/test__regional_access_boundary_utils.py‎

Lines changed: 42 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
# limitations under the License.
1414

1515
import datetime
16+
import logging
1617
from unittest import mock
1718

1819
import pytest # type: ignore
@@ -24,6 +25,23 @@
2425
from google.oauth2 import credentials as oauth2_credentials
2526

2627

28+
@pytest.fixture
29+
def rab_caplog(caplog):
30+
"""Fixture to configure logging capture and ensure propagation for RAB utilities."""
31+
32+
caplog.set_level(
33+
logging.DEBUG, logger="google.auth._regional_access_boundary_utils"
34+
)
35+
36+
google_logger = logging.getLogger("google")
37+
original_propagate = google_logger.propagate
38+
google_logger.propagate = True
39+
try:
40+
yield caplog
41+
finally:
42+
google_logger.propagate = original_propagate
43+
44+
2745
class CredentialsImpl(credentials.CredentialsWithRegionalAccessBoundary):
2846
def __init__(self, universe_domain=None):
2947
super(CredentialsImpl, self).__init__()
@@ -379,7 +397,7 @@ def test_lookup_regional_access_boundary_success(self, mock_lookup_rab):
379397
assert rab_manager._data.cooldown_expiry is None
380398

381399
@mock.patch.object(CredentialsImpl, "_lookup_regional_access_boundary")
382-
def test_lookup_regional_access_boundary_failure(self, mock_lookup_rab):
400+
def test_lookup_regional_access_boundary_failure(self, mock_lookup_rab, rab_caplog):
383401
creds = CredentialsImpl()
384402
request = mock.Mock()
385403
rab_manager = _regional_access_boundary_utils._RegionalAccessBoundaryManager()
@@ -396,6 +414,13 @@ def test_lookup_regional_access_boundary_failure(self, mock_lookup_rab):
396414
assert rab_manager._data.expiry is None
397415
assert rab_manager._data.cooldown_expiry is not None
398416

417+
# RAB failures should be logged at DEBUG level.
418+
assert any(
419+
t[1] == logging.DEBUG
420+
and "Regional Access Boundary lookup failed. Entering cooldown." in t[2]
421+
for t in rab_caplog.record_tuples
422+
)
423+
399424
def test_lookup_regional_access_boundary_null_url(self):
400425
creds = oauth2_credentials.Credentials(token="token")
401426
request = mock.Mock()
@@ -441,7 +466,9 @@ def test_regional_access_boundary_refresh_thread_run_success(self, mock_utcnow):
441466
assert rab_manager._data.cooldown_expiry is None
442467

443468
@mock.patch("google.auth._helpers.utcnow")
444-
def test_regional_access_boundary_refresh_thread_run_failure(self, mock_utcnow):
469+
def test_regional_access_boundary_refresh_thread_run_failure(
470+
self, mock_utcnow, rab_caplog
471+
):
445472
mock_now = datetime.datetime(2025, 1, 1, 12, 0, 0)
446473
mock_utcnow.return_value = mock_now
447474

@@ -466,6 +493,19 @@ def test_regional_access_boundary_refresh_thread_run_failure(self, mock_utcnow):
466493
assert rab_manager._data.cooldown_expiry == expected_cooldown_expiry
467494
assert rab_manager._data.cooldown_duration == initial_cooldown * 2
468495

496+
# RAB failures should be logged at DEBUG level.
497+
assert any(
498+
t[1] == logging.DEBUG
499+
and "Asynchronous Regional Access Boundary lookup raised an exception"
500+
in t[2]
501+
for t in rab_caplog.record_tuples
502+
)
503+
assert any(
504+
t[1] == logging.DEBUG
505+
and "Regional Access Boundary lookup failed. Entering cooldown." in t[2]
506+
for t in rab_caplog.record_tuples
507+
)
508+
469509
@mock.patch("google.auth._helpers.utcnow")
470510
def test_regional_access_boundary_refresh_thread_run_failure_hard_expiry(
471511
self, mock_utcnow

‎packages/google-auth/tests_async/test__regional_access_boundary_utils.py‎

Lines changed: 5 additions & 42 deletions
Original file line numberDiff line numberDiff line change
@@ -195,63 +195,26 @@ def test_async_refresh_manager_pickle():
195195

196196

197197
@pytest.mark.asyncio
198-
async def test_async_worker_exception_logging_enabled(monkeypatch):
198+
async def test_async_worker_exception_logging():
199199
credentials = mock.AsyncMock()
200200
credentials._lookup_regional_access_boundary.side_effect = Exception("lookup fail")
201201

202202
request = mock.Mock()
203203
request._clone.return_value = request
204204
rab_manager = mock.Mock()
205205

206-
# Force is_logging_enabled to return True
207-
monkeypatch.setattr(
208-
_regional_access_boundary_utils._helpers,
209-
"is_logging_enabled",
210-
lambda logger: True,
211-
)
212-
213-
manager = (
214-
_regional_access_boundary_utils._AsyncRegionalAccessBoundaryRefreshManager()
215-
)
216-
217-
with mock.patch.object(
218-
_regional_access_boundary_utils._LOGGER, "warning"
219-
) as mock_warning:
220-
manager.start_refresh(credentials, request, rab_manager)
221-
await manager._worker_task
222-
223-
mock_warning.assert_called_once()
224-
assert "lookup raised an exception" in mock_warning.call_args[0][0]
225-
rab_manager.process_regional_access_boundary_info.assert_called_once_with(None)
226-
227-
228-
@pytest.mark.asyncio
229-
async def test_async_worker_exception_logging_disabled(monkeypatch):
230-
credentials = mock.AsyncMock()
231-
credentials._lookup_regional_access_boundary.side_effect = Exception("lookup fail")
232-
233-
request = mock.Mock()
234-
request._clone.return_value = request
235-
rab_manager = mock.Mock()
236-
237-
# Force is_logging_enabled to return False
238-
monkeypatch.setattr(
239-
_regional_access_boundary_utils._helpers,
240-
"is_logging_enabled",
241-
lambda logger: False,
242-
)
243-
244206
manager = (
245207
_regional_access_boundary_utils._AsyncRegionalAccessBoundaryRefreshManager()
246208
)
247209

248210
with mock.patch.object(
249-
_regional_access_boundary_utils._LOGGER, "warning"
250-
) as mock_warning:
211+
_regional_access_boundary_utils._LOGGER, "debug"
212+
) as mock_debug:
251213
manager.start_refresh(credentials, request, rab_manager)
252214
await manager._worker_task
253215

254-
mock_warning.assert_not_called()
216+
mock_debug.assert_called_once()
217+
assert "lookup raised an exception" in mock_debug.call_args[0][0]
255218
rab_manager.process_regional_access_boundary_info.assert_called_once_with(None)
256219

257220

0 commit comments

Comments
 (0)