mirror of
https://github.com/home-assistant/core.git
synced 2025-07-20 11:47:06 +00:00
Improve rest error logging (#147736)
* Improve rest error logging * Improve rest error logging * Improve rest error logging * Improve rest error logging * Improve rest error logging * top level
This commit is contained in:
J. Nick Koston
GitHub
parent
1f3bdfc7b7
commit
f8c052e0ce
@ -6,6 +6,7 @@ import logging
|
||||
from typing import Any
|
||||
|
||||
import aiohttp
|
||||
from aiohttp import hdrs
|
||||
from multidict import CIMultiDictProxy
|
||||
import xmltodict
|
||||
|
||||
@ -77,6 +78,12 @@ class RestData:
|
||||
"""Set url."""
|
||||
self._resource = url
|
||||
|
||||
def _is_expected_content_type(self, content_type: str) -> bool:
|
||||
"""Check if the content type is one we expect (JSON or XML)."""
|
||||
return content_type.startswith(
|
||||
("application/json", "text/json", *XML_MIME_TYPES)
|
||||
)
|
||||
|
||||
def data_without_xml(self) -> str | None:
|
||||
"""If the data is an XML string, convert it to a JSON string."""
|
||||
_LOGGER.debug("Data fetched from resource: %s", self.data)
|
||||
@ -84,7 +91,7 @@ class RestData:
|
||||
(value := self.data) is not None
|
||||
# If the http request failed, headers will be None
|
||||
and (headers := self.headers) is not None
|
||||
and (content_type := headers.get("content-type"))
|
||||
and (content_type := headers.get(hdrs.CONTENT_TYPE))
|
||||
and content_type.startswith(XML_MIME_TYPES)
|
||||
):
|
||||
value = json_dumps(xmltodict.parse(value))
|
||||
@ -120,6 +127,7 @@ class RestData:
|
||||
# Handle data/content
|
||||
if self._request_data:
|
||||
request_kwargs["data"] = self._request_data
|
||||
response = None
|
||||
try:
|
||||
# Make the request
|
||||
async with self._session.request(
|
||||
@ -143,3 +151,34 @@ class RestData:
|
||||
self.last_exception = ex
|
||||
self.data = None
|
||||
self.headers = None
|
||||
|
||||
# Log response details outside the try block so we always get logging
|
||||
if response is None:
|
||||
return
|
||||
|
||||
# Log response details for debugging
|
||||
content_type = response.headers.get(hdrs.CONTENT_TYPE)
|
||||
_LOGGER.debug(
|
||||
"REST response from %s: status=%s, content-type=%s, length=%s",
|
||||
self._resource,
|
||||
response.status,
|
||||
content_type or "not set",
|
||||
len(self.data) if self.data else 0,
|
||||
)
|
||||
|
||||
# If we got an error response with non-JSON/XML content, log a sample
|
||||
# This helps debug issues like servers blocking with HTML error pages
|
||||
if (
|
||||
response.status >= 400
|
||||
and content_type
|
||||
and not self._is_expected_content_type(content_type)
|
||||
):
|
||||
sample = self.data[:500] if self.data else "<empty>"
|
||||
_LOGGER.warning(
|
||||
"REST request to %s returned status %s with %s response: %s%s",
|
||||
self._resource,
|
||||
response.status,
|
||||
content_type,
|
||||
sample,
|
||||
"..." if self.data and len(self.data) > 500 else "",
|
||||
)
|
||||
|
||||
444
tests/components/rest/test_data.py
Normal file
444
tests/components/rest/test_data.py
Normal file
@ -0,0 +1,444 @@
|
||||
"""Test REST data module logging improvements."""
|
||||
|
||||
import logging
|
||||
|
||||
import pytest
|
||||
|
||||
from homeassistant.components.rest import DOMAIN
|
||||
from homeassistant.core import HomeAssistant
|
||||
from homeassistant.setup import async_setup_component
|
||||
|
||||
from tests.test_util.aiohttp import AiohttpClientMocker
|
||||
|
||||
|
||||
async def test_rest_data_log_warning_on_error_status(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test that warning is logged for error status codes."""
|
||||
# Mock a 403 response with HTML content
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=403,
|
||||
text="<html><body>Access Denied</body></html>",
|
||||
headers={"Content-Type": "text/html"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.test }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check that warning was logged
|
||||
assert (
|
||||
"REST request to http://example.com/api returned status 403 "
|
||||
"with text/html response" in caplog.text
|
||||
)
|
||||
assert "<html><body>Access Denied</body></html>" in caplog.text
|
||||
|
||||
|
||||
async def test_rest_data_no_warning_on_200_with_wrong_content_type(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test that no warning is logged for 200 status with wrong content."""
|
||||
# Mock a 200 response with HTML - users might still want to parse this
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=200,
|
||||
text="<p>This is HTML, not JSON!</p>",
|
||||
headers={"Content-Type": "text/html; charset=utf-8"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Should NOT warn for 200 status, even with HTML content type
|
||||
assert (
|
||||
"REST request to http://example.com/api returned status 200" not in caplog.text
|
||||
)
|
||||
|
||||
|
||||
async def test_rest_data_no_warning_on_success_json(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test that no warning is logged for successful JSON responses."""
|
||||
# Mock a successful JSON response
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=200,
|
||||
json={"status": "ok", "value": 42},
|
||||
headers={"Content-Type": "application/json"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.value }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check that no warning was logged
|
||||
assert "REST request to http://example.com/api returned status" not in caplog.text
|
||||
|
||||
|
||||
async def test_rest_data_no_warning_on_success_xml(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test that no warning is logged for successful XML responses."""
|
||||
# Mock a successful XML response
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=200,
|
||||
text='<?xml version="1.0"?><root><value>42</value></root>',
|
||||
headers={"Content-Type": "application/xml"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.root.value }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check that no warning was logged
|
||||
assert "REST request to http://example.com/api returned status" not in caplog.text
|
||||
|
||||
|
||||
async def test_rest_data_warning_truncates_long_responses(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test that warning truncates very long response bodies."""
|
||||
# Create a very long error message
|
||||
long_message = "Error: " + "x" * 1000
|
||||
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=500,
|
||||
text=long_message,
|
||||
headers={"Content-Type": "text/plain"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.test }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check that warning was logged with truncation
|
||||
# Set the logger filter to only check our specific logger
|
||||
caplog.set_level(logging.WARNING, logger="homeassistant.components.rest.data")
|
||||
|
||||
# Verify the truncated warning appears
|
||||
assert (
|
||||
"REST request to http://example.com/api returned status 500 "
|
||||
"with text/plain response: Error: " + "x" * 493 + "..." in caplog.text
|
||||
)
|
||||
|
||||
|
||||
async def test_rest_data_debug_logging_shows_response_details(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test that debug logging shows response details."""
|
||||
caplog.set_level(logging.DEBUG)
|
||||
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=200,
|
||||
json={"test": "data"},
|
||||
headers={"Content-Type": "application/json"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.test }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check debug log
|
||||
assert (
|
||||
"REST response from http://example.com/api: status=200, "
|
||||
"content-type=application/json, length=" in caplog.text
|
||||
)
|
||||
|
||||
|
||||
async def test_rest_data_no_content_type_header(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test handling of responses without Content-Type header."""
|
||||
caplog.set_level(logging.DEBUG)
|
||||
|
||||
# Mock response without Content-Type header
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=200,
|
||||
text="plain text response",
|
||||
headers={}, # No Content-Type
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check debug log shows "not set"
|
||||
assert "content-type=not set" in caplog.text
|
||||
# No warning for 200 with missing content-type
|
||||
assert "REST request to http://example.com/api returned status" not in caplog.text
|
||||
|
||||
|
||||
async def test_rest_data_real_world_bom_blocking_scenario(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test real-world scenario where BOM blocks with HTML response."""
|
||||
# Mock BOM blocking response
|
||||
bom_block_html = "<p>Your access is blocked due to automated access</p>"
|
||||
|
||||
aioclient_mock.get(
|
||||
"http://www.bom.gov.au/fwo/IDN60901/IDN60901.94767.json",
|
||||
status=403,
|
||||
text=bom_block_html,
|
||||
headers={"Content-Type": "text/html"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": ("http://www.bom.gov.au/fwo/IDN60901/IDN60901.94767.json"),
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "bom_temperature",
|
||||
"value_template": (
|
||||
"{{ value_json.observations.data[0].air_temp }}"
|
||||
),
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check that warning was logged with clear indication of the issue
|
||||
assert (
|
||||
"REST request to http://www.bom.gov.au/fwo/IDN60901/"
|
||||
"IDN60901.94767.json returned status 403 with text/html response"
|
||||
) in caplog.text
|
||||
assert "Your access is blocked" in caplog.text
|
||||
|
||||
|
||||
async def test_rest_data_warning_on_html_error(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test that warning is logged for error status with HTML content."""
|
||||
# Mock a 404 response with HTML error page
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
status=404,
|
||||
text="<html><body><h1>404 Not Found</h1></body></html>",
|
||||
headers={"Content-Type": "text/html"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.test }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Should warn for error status with HTML
|
||||
assert (
|
||||
"REST request to http://example.com/api returned status 404 "
|
||||
"with text/html response" in caplog.text
|
||||
)
|
||||
assert "<html><body><h1>404 Not Found</h1></body></html>" in caplog.text
|
||||
|
||||
|
||||
async def test_rest_data_no_warning_on_json_error(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test POST request that returns JSON error - no warning expected."""
|
||||
aioclient_mock.post(
|
||||
"http://example.com/api",
|
||||
status=400,
|
||||
text='{"error": "Invalid request payload"}',
|
||||
headers={"Content-Type": "application/json"},
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "POST",
|
||||
"payload": '{"data": "test"}',
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.error }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Should NOT warn for JSON error responses - users can parse these
|
||||
assert (
|
||||
"REST request to http://example.com/api returned status 400" not in caplog.text
|
||||
)
|
||||
|
||||
|
||||
async def test_rest_data_timeout_error(
|
||||
hass: HomeAssistant,
|
||||
aioclient_mock: AiohttpClientMocker,
|
||||
caplog: pytest.LogCaptureFixture,
|
||||
) -> None:
|
||||
"""Test timeout error logging."""
|
||||
aioclient_mock.get(
|
||||
"http://example.com/api",
|
||||
exc=TimeoutError(),
|
||||
)
|
||||
|
||||
assert await async_setup_component(
|
||||
hass,
|
||||
DOMAIN,
|
||||
{
|
||||
DOMAIN: {
|
||||
"resource": "http://example.com/api",
|
||||
"method": "GET",
|
||||
"timeout": 10,
|
||||
"sensor": [
|
||||
{
|
||||
"name": "test_sensor",
|
||||
"value_template": "{{ value_json.test }}",
|
||||
}
|
||||
],
|
||||
}
|
||||
},
|
||||
)
|
||||
await hass.async_block_till_done()
|
||||
|
||||
# Check timeout error is logged or platform reports not ready
|
||||
assert (
|
||||
"Timeout while fetching data: http://example.com/api" in caplog.text
|
||||
or "Platform rest not ready yet" in caplog.text
|
||||
)
|
||||
Loading…
x
Reference in New Issue
Block a user