diff --git a/homeassistant/components/splunk/__init__.py b/homeassistant/components/splunk/__init__.py index 9d7b038d3edd..82d1fd0438ed 100644 --- a/homeassistant/components/splunk/__init__.py +++ b/homeassistant/components/splunk/__init__.py @@ -143,8 +143,19 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry) -> bool: await event_collector.queue(json.dumps(payload, cls=JSONEncoder), send=False) + send_failing = False + + def log_send_failure(level: int, message: str, *args: Any) -> None: + """Log a send failure, demoting it to debug while an outage is open.""" + nonlocal send_failing + + _LOGGER.log(logging.DEBUG if send_failing else level, message, *args) + send_failing = True + async def splunk_event_listener(event: Event[EventStateChangedData]) -> None: """Listen for new messages on the bus and sends them to Splunk.""" + nonlocal send_failing + state = event.data.get("new_state") if state is None or not entity_filter(state.entity_id): return @@ -167,22 +178,47 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry) -> bool: } try: - await event_collector.queue(json.dumps(payload, cls=JSONEncoder), send=True) + sent = await event_collector.queue( + json.dumps(payload, cls=JSONEncoder), send=True + ) except SplunkPayloadError as err: if err.status == HTTPStatus.UNAUTHORIZED: - _LOGGER.error("Splunk token unauthorized: %s", err) - # Trigger reauth flow entry.async_start_reauth(hass) + log_send_failure(logging.ERROR, "Splunk token unauthorized: %s", err) else: - _LOGGER.warning("Splunk payload error: %s", err) + log_send_failure(logging.WARNING, "Splunk payload error: %s", err) + return except ClientConnectionError as err: - _LOGGER.debug("Connection error sending to Splunk: %s", err) + log_send_failure( + logging.DEBUG, "Connection error sending to Splunk: %s", err + ) + return except TimeoutError: - _LOGGER.debug("Timeout sending to Splunk at %s:%s", host, port) + log_send_failure( + logging.DEBUG, "Timeout sending to Splunk at %s:%s", host, port + ) + return except ClientResponseError as err: - _LOGGER.warning("Splunk response error: %s", err.message) + log_send_failure(logging.WARNING, "Splunk response error: %s", err.message) + return except Exception: - _LOGGER.exception("Unexpected error sending event to Splunk") + # Logged in the handler, so the traceback is still available. + _LOGGER.log( + logging.DEBUG if send_failing else logging.ERROR, + "Unexpected error sending event to Splunk", + exc_info=not send_failing, + ) + send_failing = True + return + + if not sent: + # Coalesced into an in-flight send, which says nothing about + # whether this event reached Splunk. + return + + if send_failing: + _LOGGER.info("Sending events to Splunk has recovered") + send_failing = False # Store the event listener cancellation callback entry.async_on_unload( diff --git a/tests/components/splunk/test_init.py b/tests/components/splunk/test_init.py index b0081e52b282..2a4493f13ce8 100644 --- a/tests/components/splunk/test_init.py +++ b/tests/components/splunk/test_init.py @@ -229,6 +229,11 @@ async def test_event_listener_unauthorized( logging.WARNING, "Splunk response error: Internal Server Error", ), + ( + SplunkPayloadError(0, "Bad request", HTTPStatus.BAD_REQUEST), + logging.WARNING, + "Splunk payload error: Bad request", + ), ], ) async def test_event_listener_error_handling( @@ -262,3 +267,270 @@ async def test_event_listener_error_handling( record.levelno == expected_log_level and expected_message in record.message for record in caplog.records ) + + +@pytest.mark.parametrize( + ("error", "expected_log_level", "expected_message", "expected_traceback"), + [ + ( + ClientResponseError( + request_info=MagicMock(), + history=(), + status=500, + message="Internal Server Error", + ), + logging.WARNING, + "Splunk response error: Internal Server Error", + False, + ), + ( + SplunkPayloadError(0, "Unauthorized", HTTPStatus.UNAUTHORIZED), + logging.ERROR, + "Splunk token unauthorized", + False, + ), + ( + ValueError("boom"), + logging.ERROR, + "Unexpected error sending event to Splunk", + True, + ), + ], +) +async def test_event_listener_repeated_failures_log_at_debug( + hass: HomeAssistant, + mock_hass_splunk: AsyncMock, + mock_config_entry: MockConfigEntry, + caplog: pytest.LogCaptureFixture, + error: Exception, + expected_log_level: int, + expected_message: str, + expected_traceback: bool, +) -> None: + """Test the first failure logs at its level and the repeats log at debug.""" + mock_config_entry.add_to_hass(hass) + + assert await hass.config_entries.async_setup(mock_config_entry.entry_id) + await hass.async_block_till_done() + + mock_hass_splunk.queue.side_effect = error + + with caplog.at_level(logging.DEBUG): + for i in range(5): + hass.states.async_set("sensor.test", str(i)) + await hass.async_block_till_done() + + matching_records = [ + record for record in caplog.records if expected_message in record.message + ] + assert len(matching_records) == 5 + assert matching_records[0].levelno == expected_log_level + # A traceback is worth one record per outage, never one per state change. + assert bool(matching_records[0].exc_info) is expected_traceback + assert all(record.levelno == logging.DEBUG for record in matching_records[1:]) + assert not any(record.exc_info for record in matching_records[1:]) + + +@pytest.mark.parametrize( + ("first_error", "first_message", "first_level", "second_error", "second_message"), + [ + pytest.param( + ClientConnectionError("Connection failed"), + "Connection error sending to Splunk", + logging.DEBUG, + SplunkPayloadError(0, "Unauthorized", HTTPStatus.UNAUTHORIZED), + "Splunk token unauthorized", + id="more_severe_second_failure", + ), + pytest.param( + SplunkPayloadError(0, "Unauthorized", HTTPStatus.UNAUTHORIZED), + "Splunk token unauthorized", + logging.ERROR, + ClientResponseError( + request_info=MagicMock(), + history=(), + status=500, + message="Internal Server Error", + ), + "Splunk response error: Internal Server Error", + id="less_severe_second_failure", + ), + ], +) +async def test_event_listener_different_failure_during_outage_logs_at_debug( + hass: HomeAssistant, + mock_hass_splunk: AsyncMock, + mock_config_entry: MockConfigEntry, + caplog: pytest.LogCaptureFixture, + first_error: Exception, + first_message: str, + first_level: int, + second_error: Exception, + second_message: str, +) -> None: + """Test a different failure during an outage logs at debug, whatever its level.""" + mock_config_entry.add_to_hass(hass) + + assert await hass.config_entries.async_setup(mock_config_entry.entry_id) + await hass.async_block_till_done() + + with caplog.at_level(logging.DEBUG): + mock_hass_splunk.queue.side_effect = first_error + hass.states.async_set("sensor.test", "outage") + await hass.async_block_till_done() + + mock_hass_splunk.queue.side_effect = second_error + for i in range(2): + hass.states.async_set("sensor.test", f"different-{i}") + await hass.async_block_till_done() + + first_records = [ + record for record in caplog.records if first_message in record.message + ] + assert len(first_records) == 1 + assert first_records[0].levelno == first_level + + second_records = [ + record for record in caplog.records if second_message in record.message + ] + assert len(second_records) == 2 + assert all(record.levelno == logging.DEBUG for record in second_records) + + +async def test_event_listener_recovery_logs_once_at_info( + hass: HomeAssistant, + mock_hass_splunk: AsyncMock, + mock_config_entry: MockConfigEntry, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test a recovered outage logs a single info record.""" + mock_config_entry.add_to_hass(hass) + + assert await hass.config_entries.async_setup(mock_config_entry.entry_id) + await hass.async_block_till_done() + + mock_hass_splunk.queue.side_effect = ClientConnectionError("Connection failed") + + with caplog.at_level(logging.DEBUG): + for i in range(2): + hass.states.async_set("sensor.test", str(i)) + await hass.async_block_till_done() + + mock_hass_splunk.queue.side_effect = None + for i in range(2): + hass.states.async_set("sensor.test", f"recovered-{i}") + await hass.async_block_till_done() + + recovery_records = [ + record + for record in caplog.records + if "Sending events to Splunk has recovered" in record.message + ] + assert len(recovery_records) == 1 + assert recovery_records[0].levelno == logging.INFO + + +async def test_event_listener_failure_after_recovery_logs_at_natural_level( + hass: HomeAssistant, + mock_hass_splunk: AsyncMock, + mock_config_entry: MockConfigEntry, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test a new outage after a recovery logs at its natural level again.""" + mock_config_entry.add_to_hass(hass) + + assert await hass.config_entries.async_setup(mock_config_entry.entry_id) + await hass.async_block_till_done() + + mock_hass_splunk.queue.side_effect = ClientConnectionError("Connection failed") + + with caplog.at_level(logging.DEBUG): + hass.states.async_set("sensor.test", "first-outage") + await hass.async_block_till_done() + + mock_hass_splunk.queue.side_effect = None + hass.states.async_set("sensor.test", "recovered") + await hass.async_block_till_done() + + caplog.clear() + mock_hass_splunk.queue.side_effect = ClientResponseError( + request_info=MagicMock(), + history=(), + status=500, + message="Internal Server Error", + ) + hass.states.async_set("sensor.test", "second-outage") + await hass.async_block_till_done() + + assert any( + record.levelno == logging.WARNING + and "Splunk response error: Internal Server Error" in record.message + for record in caplog.records + ) + + +async def test_event_listener_coalesced_send_is_not_a_recovery( + hass: HomeAssistant, + mock_hass_splunk: AsyncMock, + mock_config_entry: MockConfigEntry, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test a send coalesced into an in-flight send isn't treated as success. + + hass_splunk.queue() returns False, without raising, when a send is already + in flight, which says nothing about whether this event reached Splunk. + """ + mock_config_entry.add_to_hass(hass) + + assert await hass.config_entries.async_setup(mock_config_entry.entry_id) + await hass.async_block_till_done() + + error = ClientResponseError( + request_info=MagicMock(), + history=(), + status=500, + message="Internal Server Error", + ) + mock_hass_splunk.queue.side_effect = [error, False, error] + + with caplog.at_level(logging.DEBUG): + for i in range(3): + hass.states.async_set("sensor.test", str(i)) + await hass.async_block_till_done() + + assert not any( + "Sending events to Splunk has recovered" in record.message + for record in caplog.records + ) + + # Still demoted, so the coalesced send did not clear the outage either. + failure_records = [ + record + for record in caplog.records + if "Splunk response error: Internal Server Error" in record.message + ] + assert len(failure_records) == 2 + assert failure_records[0].levelno == logging.WARNING + assert failure_records[1].levelno == logging.DEBUG + + +async def test_event_listener_no_recovery_message_without_prior_failure( + hass: HomeAssistant, + mock_hass_splunk: AsyncMock, + mock_config_entry: MockConfigEntry, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test that a successful send without prior failures logs no recovery message.""" + mock_config_entry.add_to_hass(hass) + + assert await hass.config_entries.async_setup(mock_config_entry.entry_id) + await hass.async_block_till_done() + + with caplog.at_level(logging.DEBUG): + hass.states.async_set("sensor.test", "123") + await hass.async_block_till_done() + + assert not any( + "Sending events to Splunk has recovered" in record.message + for record in caplog.records + )