diff --git a/changelog.d/+log-x-request-id-on-5xx.added.md b/changelog.d/+log-x-request-id-on-5xx.added.md new file mode 100644 index 00000000..a242f188 --- /dev/null +++ b/changelog.d/+log-x-request-id-on-5xx.added.md @@ -0,0 +1 @@ +On 5xx responses, the SDK now logs the Meraki `X-Request-Id` response header so it can be shared with Meraki to look up the request in server-side logs. If the header is absent, `none` is logged in its place. After retries are exhausted, the request ID is also logged at error level. diff --git a/meraki/aio/rest_session.py b/meraki/aio/rest_session.py index 9eb35572..aba94507 100644 --- a/meraki/aio/rest_session.py +++ b/meraki/aio/rest_session.py @@ -230,8 +230,17 @@ async def _request(self, metadata, method, url, **kwargs): await asyncio.sleep(wait) # 5XX errors elif status >= 500: + request_id = response.headers.get("X-Request-Id") or "none" if self._logger: - self._logger.warning(f"{tag}, {operation} > {abs_url} - {status} {reason}, retrying in 1 second") + self._logger.warning( + f"{tag}, {operation} > {abs_url} - {status} {reason} " + f"(X-Request-Id: {request_id}), retrying in 1 second" + ) + if _attempt == retries - 1: + self._logger.error( + f"{tag}, {operation} > {abs_url} - {status} {reason} failed after retries. " + f"Provide this X-Request-Id to Meraki for log lookup: {request_id}" + ) await asyncio.sleep(1) # 4XX errors else: diff --git a/meraki/rest_session.py b/meraki/rest_session.py index 889f6693..0832410e 100644 --- a/meraki/rest_session.py +++ b/meraki/rest_session.py @@ -306,11 +306,19 @@ def request(self, metadata, method, url, **kwargs): raise APIError(metadata, response) # Handle 5xx errors case status if 500 <= status: + request_id = response.headers.get("X-Request-Id") or "none" if self._logger: - self._logger.warning(f"{tag}, {operation} - {status} {reason}, retrying in 1 second") + self._logger.warning( + f"{tag}, {operation} - {status} {reason} (X-Request-Id: {request_id}), retrying in 1 second" + ) time.sleep(1) retries -= 1 if retries == 0: + if self._logger: + self._logger.error( + f"{tag}, {operation} - {status} {reason} failed after retries. " + f"Provide this X-Request-Id to Meraki for log lookup: {request_id}" + ) raise APIError(metadata, response) # Handle other 4xx errors case status if status != 429 and 400 <= status < 500: diff --git a/tests/unit/test_aio_rest_session.py b/tests/unit/test_aio_rest_session.py index e14f9131..d198b50f 100644 --- a/tests/unit/test_aio_rest_session.py +++ b/tests/unit/test_aio_rest_session.py @@ -363,6 +363,59 @@ async def test_retry_on_500(self, async_session): result = await async_session._request(_metadata(), "GET", "/organizations") assert result.status == 200 + @pytest.mark.asyncio + async def test_request_id_logged_in_warning(self, async_session_with_logger): + session = async_session_with_logger + resp_500 = _mock_aio_response( + 500, + reason="Internal Server Error", + headers={"X-Request-Id": "abc123def456"}, + ) + resp_200 = _mock_aio_response(200) + session._req_session.request = AsyncMock(side_effect=[resp_500, resp_200]) + + with patch(SLEEP_PATCH, side_effect=_noop_sleep): + result = await session._request(_metadata(), "GET", "/organizations") + + assert result.status == 200 + warning_messages = [c.args[0] for c in session._logger.warning.call_args_list] + assert any("X-Request-Id: abc123def456" in m for m in warning_messages) + + @pytest.mark.asyncio + async def test_request_id_logged_as_error_after_exhausting_retries(self, async_session_with_logger): + session = async_session_with_logger + session._maximum_retries = 2 + resp_500 = _mock_aio_response( + 500, + reason="Internal Server Error", + headers={"X-Request-Id": "deadbeef00112233"}, + ) + session._req_session.request = AsyncMock(return_value=resp_500) + + with patch(SLEEP_PATCH, side_effect=_noop_sleep): + with pytest.raises(AsyncAPIError): + await session._request(_metadata(), "GET", "/organizations") + + error_messages = [c.args[0] for c in session._logger.error.call_args_list] + assert any("deadbeef00112233" in m for m in error_messages) + assert any("Provide this X-Request-Id to Meraki" in m for m in error_messages) + + @pytest.mark.asyncio + async def test_no_request_id_logs_none(self, async_session_with_logger): + session = async_session_with_logger + session._maximum_retries = 2 + resp_500 = _mock_aio_response(500, reason="Internal Server Error", headers={}) + session._req_session.request = AsyncMock(return_value=resp_500) + + with patch(SLEEP_PATCH, side_effect=_noop_sleep): + with pytest.raises(AsyncAPIError): + await session._request(_metadata(), "GET", "/organizations") + + warning_messages = [c.args[0] for c in session._logger.warning.call_args_list] + assert any("X-Request-Id: none" in m for m in warning_messages) + error_messages = [c.args[0] for c in session._logger.error.call_args_list] + assert any("log lookup: none" in m for m in error_messages) + @pytest.mark.asyncio async def test_5xx_raises_after_max_retries(self, async_session): async_session._maximum_retries = 2 diff --git a/tests/unit/test_rest_session.py b/tests/unit/test_rest_session.py index 1fb4b58a..e6fe4035 100644 --- a/tests/unit/test_rest_session.py +++ b/tests/unit/test_rest_session.py @@ -32,6 +32,31 @@ def session(): return s +@pytest.fixture +def session_with_logger(): + with patch("meraki.rest_session.check_python_version"): + s = RestSession( + logger=MagicMock(), + api_key="fake_api_key_1234567890123456789012345678901234567890", + base_url="https://api.meraki.com/api/v1", + single_request_timeout=60, + certificate_path="", + requests_proxy="", + wait_on_rate_limit=True, + nginx_429_retry_wait_time=2, + action_batch_retry_wait_time=2, + network_delete_retry_wait_time=2, + retry_4xx_error=False, + retry_4xx_error_wait_time=1, + maximum_retries=2, + simulate=False, + be_geo_id="", + caller="TestApp TestVendor", + use_iterator_for_get_pages=False, + ) + return s + + def _metadata(operation="getOrganizations", tags=None): return {"tags": tags or ["organizations"], "operation": operation} @@ -172,6 +197,61 @@ def test_5xx_raises_after_max_retries(self, mock_sleep, session): with pytest.raises(APIError): session.request(_metadata(), "GET", "/organizations") + +# --- X-Request-Id logging on 5xx --- + + +class TestRequestIdLoggingOn5xx: + @patch("time.sleep", return_value=None) + def test_request_id_logged_in_warning(self, mock_sleep, session_with_logger): + session = session_with_logger + resp_500 = _mock_response( + 500, + reason="Internal Server Error", + headers={"X-Request-Id": "abc123def456"}, + ) + resp_200 = _mock_response(200) + session._req_session.request = MagicMock(side_effect=[resp_500, resp_200]) + + result = session.request(_metadata(), "GET", "/organizations") + + assert result.status_code == 200 + warning_messages = [c.args[0] for c in session._logger.warning.call_args_list] + assert any("X-Request-Id: abc123def456" in m for m in warning_messages) + + @patch("time.sleep", return_value=None) + def test_request_id_logged_as_error_after_exhausting_retries(self, mock_sleep, session_with_logger): + session = session_with_logger + session._maximum_retries = 2 + resp_500 = _mock_response( + 500, + reason="Internal Server Error", + headers={"X-Request-Id": "deadbeef00112233"}, + ) + session._req_session.request = MagicMock(return_value=resp_500) + + with pytest.raises(APIError): + session.request(_metadata(), "GET", "/organizations") + + error_messages = [c.args[0] for c in session._logger.error.call_args_list] + assert any("deadbeef00112233" in m for m in error_messages) + assert any("Provide this X-Request-Id to Meraki" in m for m in error_messages) + + @patch("time.sleep", return_value=None) + def test_no_request_id_logs_none(self, mock_sleep, session_with_logger): + session = session_with_logger + session._maximum_retries = 2 + resp_500 = _mock_response(500, reason="Internal Server Error", headers={}) + session._req_session.request = MagicMock(return_value=resp_500) + + with pytest.raises(APIError): + session.request(_metadata(), "GET", "/organizations") + + warning_messages = [c.args[0] for c in session._logger.warning.call_args_list] + assert any("X-Request-Id: none" in m for m in warning_messages) + error_messages = [c.args[0] for c in session._logger.error.call_args_list] + assert any("log lookup: none" in m for m in error_messages) + @patch("time.sleep", return_value=None) def test_retry_on_connection_error(self, mock_sleep, session): exc = requests.exceptions.ConnectionError("Connection refused")