From 70e3da207a7df4394f9bcee25d0d35d715f483f1 Mon Sep 17 00:00:00 2001 From: Raman Gupta <7243222+raman325@users.noreply.github.com> Date: Wed, 27 Sep 2023 01:17:52 -0400 Subject: [PATCH] Automatically enable/disable zwave_js server logging in lib (#100837) * Bump zwave-js-server-python to 0.52.0 * Add WS command to enabled zwave_js server logging in lib * enable and disable server logging automatically * fix conditionals * fix tests * Add logging * small tweaks * Add logger as a dependency * fix test * Prepare for movement of event constant * Add constant so tests pass --- homeassistant/components/zwave_js/__init__.py | 25 +++++ homeassistant/components/zwave_js/api.py | 7 +- homeassistant/components/zwave_js/const.py | 2 + homeassistant/components/zwave_js/helpers.py | 79 ++++++++++++++-- .../components/zwave_js/manifest.json | 2 +- tests/components/zwave_js/test_api.py | 3 + tests/components/zwave_js/test_init.py | 94 +++++++++++++++++++ 7 files changed, 200 insertions(+), 12 deletions(-) diff --git a/homeassistant/components/zwave_js/__init__.py b/homeassistant/components/zwave_js/__init__.py index 2ff4f40a5ad..b9a26630406 100644 --- a/homeassistant/components/zwave_js/__init__.py +++ b/homeassistant/components/zwave_js/__init__.py @@ -5,6 +5,7 @@ import asyncio from collections import defaultdict from collections.abc import Coroutine from contextlib import suppress +import logging from typing import Any from zwave_js_server.client import Client as ZwaveClient @@ -29,6 +30,7 @@ from homeassistant.const import ( ATTR_ENTITY_ID, CONF_URL, EVENT_HOMEASSISTANT_STOP, + EVENT_LOGGING_CHANGED, Platform, ) from homeassistant.core import Event, HomeAssistant, callback @@ -93,6 +95,7 @@ from .const import ( DATA_CLIENT, DOMAIN, EVENT_DEVICE_ADDED_TO_REGISTRY, + LIB_LOGGER, LOGGER, USER_AGENT, ZWAVE_JS_NOTIFICATION_EVENT, @@ -105,6 +108,8 @@ from .discovery import ( async_discover_single_value, ) from .helpers import ( + async_disable_server_logging_if_needed, + async_enable_server_logging_if_needed, async_enable_statistics, get_device_id, get_device_id_ext, @@ -249,6 +254,24 @@ class DriverEvents: elif opted_in is False: await driver.async_disable_statistics() + async def handle_logging_changed(_: Event | None = None) -> None: + """Handle logging changed event.""" + if LIB_LOGGER.isEnabledFor(logging.DEBUG): + await async_enable_server_logging_if_needed( + self.hass, self.config_entry, driver + ) + else: + await async_disable_server_logging_if_needed( + self.hass, self.config_entry, driver + ) + + # Set up server logging on setup if needed + await handle_logging_changed() + + self.config_entry.async_on_unload( + self.hass.bus.async_listen(EVENT_LOGGING_CHANGED, handle_logging_changed) + ) + # Check for nodes that no longer exist and remove them stored_devices = dr.async_entries_for_config_entry( self.dev_reg, self.config_entry.entry_id @@ -902,6 +925,8 @@ async def async_unload_entry(hass: HomeAssistant, entry: ConfigEntry) -> bool: unload_ok = all(await asyncio.gather(*tasks)) if tasks else True + if hasattr(driver_events, "driver"): + await async_disable_server_logging_if_needed(hass, entry, driver_events.driver) if DATA_CLIENT_LISTEN_TASK in info: await disconnect_client(hass, entry) diff --git a/homeassistant/components/zwave_js/api.py b/homeassistant/components/zwave_js/api.py index 314b53456aa..8658dc1cc1f 100644 --- a/homeassistant/components/zwave_js/api.py +++ b/homeassistant/components/zwave_js/api.py @@ -82,7 +82,6 @@ from .const import ( from .helpers import ( async_enable_statistics, async_get_node_from_device_id, - async_update_data_collection_preference, get_device_id, ) @@ -490,6 +489,7 @@ async def websocket_network_status( "state": "connected" if client.connected else "disconnected", "driver_version": client_version_info.driver_version, "server_version": client_version_info.server_version, + "server_logging_enabled": client.server_logging_enabled, }, "controller": { "home_id": controller.home_id, @@ -1875,7 +1875,10 @@ async def websocket_update_data_collection_preference( ) -> None: """Update preference for data collection and enable/disable collection.""" opted_in = msg[OPTED_IN] - async_update_data_collection_preference(hass, entry, opted_in) + if entry.data.get(CONF_DATA_COLLECTION_OPTED_IN) != opted_in: + new_data = entry.data.copy() + new_data[CONF_DATA_COLLECTION_OPTED_IN] = opted_in + hass.config_entries.async_update_entry(entry, data=new_data) if opted_in: await async_enable_statistics(driver) diff --git a/homeassistant/components/zwave_js/const.py b/homeassistant/components/zwave_js/const.py index 5ee8b300603..34c6fa3363e 100644 --- a/homeassistant/components/zwave_js/const.py +++ b/homeassistant/components/zwave_js/const.py @@ -31,10 +31,12 @@ CONF_DATA_COLLECTION_OPTED_IN = "data_collection_opted_in" DOMAIN = "zwave_js" DATA_CLIENT = "client" +DATA_OLD_SERVER_LOG_LEVEL = "old_server_log_level" EVENT_DEVICE_ADDED_TO_REGISTRY = f"{DOMAIN}_device_added_to_registry" LOGGER = logging.getLogger(__package__) +LIB_LOGGER = logging.getLogger("zwave_js_server") # constants extra state attributes ATTR_RESERVED_VALUES = "reserved_values" # ConfigurationValue number entities diff --git a/homeassistant/components/zwave_js/helpers.py b/homeassistant/components/zwave_js/helpers.py index a163b8636e8..8774bcea73f 100644 --- a/homeassistant/components/zwave_js/helpers.py +++ b/homeassistant/components/zwave_js/helpers.py @@ -8,8 +8,14 @@ from typing import Any, cast import voluptuous as vol from zwave_js_server.client import Client as ZwaveClient -from zwave_js_server.const import CommandClass, ConfigurationValueType +from zwave_js_server.const import ( + LOG_LEVEL_MAP, + CommandClass, + ConfigurationValueType, + LogLevel, +) from zwave_js_server.model.driver import Driver +from zwave_js_server.model.log_config import LogConfig from zwave_js_server.model.node import Node as ZwaveNode from zwave_js_server.model.value import ( ConfigurationValue, @@ -39,9 +45,10 @@ from .const import ( ATTR_ENDPOINT, ATTR_PROPERTY, ATTR_PROPERTY_KEY, - CONF_DATA_COLLECTION_OPTED_IN, DATA_CLIENT, + DATA_OLD_SERVER_LOG_LEVEL, DOMAIN, + LIB_LOGGER, LOGGER, ) @@ -127,14 +134,68 @@ async def async_enable_statistics(driver: Driver) -> None: await driver.async_enable_statistics("Home Assistant", HA_VERSION) -@callback -def async_update_data_collection_preference( - hass: HomeAssistant, entry: ConfigEntry, preference: bool +async def async_enable_server_logging_if_needed( + hass: HomeAssistant, entry: ConfigEntry, driver: Driver ) -> None: - """Update data collection preference on config entry.""" - new_data = entry.data.copy() - new_data[CONF_DATA_COLLECTION_OPTED_IN] = preference - hass.config_entries.async_update_entry(entry, data=new_data) + """Enable logging of zwave-js-server in the lib.""" + # If lib log level is set to debug, we want to enable server logging. First we + # check if server log level is less verbose than library logging, and if so, set it + # to debug to match library logging. We will store the old server log level in + # hass.data so we can reset it later + if ( + not driver + or not driver.client.connected + or driver.client.server_logging_enabled + ): + return + + LOGGER.info("Enabling zwave-js-server logging") + if (curr_server_log_level := driver.log_config.level) and ( + LOG_LEVEL_MAP[curr_server_log_level] + ) > (lib_log_level := LIB_LOGGER.getEffectiveLevel()): + entry_data = hass.data[DOMAIN][entry.entry_id] + LOGGER.warning( + ( + "Server logging is set to %s and is currently less verbose " + "than library logging, setting server log level to %s to match" + ), + curr_server_log_level, + logging.getLevelName(lib_log_level), + ) + entry_data[DATA_OLD_SERVER_LOG_LEVEL] = curr_server_log_level + await driver.async_update_log_config(LogConfig(level=LogLevel.DEBUG)) + await driver.client.enable_server_logging() + LOGGER.info("Zwave-js-server logging is enabled") + + +async def async_disable_server_logging_if_needed( + hass: HomeAssistant, entry: ConfigEntry, driver: Driver +) -> None: + """Disable logging of zwave-js-server in the lib if still connected to server.""" + entry_data = hass.data[DOMAIN][entry.entry_id] + if ( + not driver + or not driver.client.connected + or not driver.client.server_logging_enabled + ): + return + LOGGER.info("Disabling zwave_js server logging") + if ( + DATA_OLD_SERVER_LOG_LEVEL in entry_data + and (old_server_log_level := entry_data.pop(DATA_OLD_SERVER_LOG_LEVEL)) + != driver.log_config.level + ): + LOGGER.info( + ( + "Server logging is currently set to %s as a result of server logging " + "being enabled. It is now being reset to %s" + ), + driver.log_config.level, + old_server_log_level, + ) + await driver.async_update_log_config(LogConfig(level=old_server_log_level)) + await driver.client.disable_server_logging() + LOGGER.info("Zwave-js-server logging is enabled") def get_valueless_base_unique_id(driver: Driver, node: ZwaveNode) -> str: diff --git a/homeassistant/components/zwave_js/manifest.json b/homeassistant/components/zwave_js/manifest.json index 4c697a9c2b7..3e8a5e4f757 100644 --- a/homeassistant/components/zwave_js/manifest.json +++ b/homeassistant/components/zwave_js/manifest.json @@ -3,7 +3,7 @@ "name": "Z-Wave", "codeowners": ["@home-assistant/z-wave"], "config_flow": true, - "dependencies": ["usb", "http", "repairs", "websocket_api"], + "dependencies": ["http", "repairs", "usb", "websocket_api"], "documentation": "https://www.home-assistant.io/integrations/zwave_js", "integration_type": "hub", "iot_class": "local_push", diff --git a/tests/components/zwave_js/test_api.py b/tests/components/zwave_js/test_api.py index 0c0b3c7e132..965b1ea4f1b 100644 --- a/tests/components/zwave_js/test_api.py +++ b/tests/components/zwave_js/test_api.py @@ -126,12 +126,14 @@ async def test_network_status( hass: HomeAssistant, multisensor_6, controller_state, + client, integration, hass_ws_client: WebSocketGenerator, ) -> None: """Test the network status websocket command.""" entry = integration ws_client = await hass_ws_client(hass) + client.server_logging_enabled = False # Try API call with entry ID with patch( @@ -150,6 +152,7 @@ async def test_network_status( assert result["client"]["ws_server_url"] == "ws://test:3000/zjs" assert result["client"]["server_version"] == "1.0.0" + assert not result["client"]["server_logging_enabled"] assert result["controller"]["inclusion_state"] == InclusionState.IDLE # Try API call with device ID diff --git a/tests/components/zwave_js/test_init.py b/tests/components/zwave_js/test_init.py index 6985a7bf252..1203997839e 100644 --- a/tests/components/zwave_js/test_init.py +++ b/tests/components/zwave_js/test_init.py @@ -1,6 +1,7 @@ """Test the Z-Wave JS init module.""" import asyncio from copy import deepcopy +import logging from unittest.mock import AsyncMock, call, patch import pytest @@ -11,6 +12,7 @@ from zwave_js_server.model.node import Node from zwave_js_server.model.version import VersionInfo from homeassistant.components.hassio.handler import HassioAPIError +from homeassistant.components.logger import DOMAIN as LOGGER_DOMAIN, SERVICE_SET_LEVEL from homeassistant.components.persistent_notification import async_dismiss from homeassistant.components.zwave_js import DOMAIN from homeassistant.components.zwave_js.helpers import get_device_id @@ -23,6 +25,7 @@ from homeassistant.helpers import ( entity_registry as er, issue_registry as ir, ) +from homeassistant.setup import async_setup_component from .common import AIR_TEMPERATURE_SENSOR, EATON_RF9640_ENTITY @@ -1550,3 +1553,94 @@ async def test_identify_event( assert len(notifications) == 1 assert list(notifications)[0] == msg_id assert "network with the home ID `3245146787`" in notifications[msg_id]["message"] + + +async def test_server_logging(hass: HomeAssistant, client) -> None: + """Test automatic server logging functionality.""" + + def _reset_mocks(): + client.async_send_command.reset_mock() + client.enable_server_logging.reset_mock() + client.disable_server_logging.reset_mock() + + # Set server logging to disabled + client.server_logging_enabled = False + + entry = MockConfigEntry(domain="zwave_js", data={"url": "ws://test.org"}) + entry.add_to_hass(hass) + + await hass.config_entries.async_setup(entry.entry_id) + await hass.async_block_till_done() + + # Setup logger and set log level to debug to trigger event listener + assert await async_setup_component(hass, "logger", {"logger": {}}) + assert logging.getLogger("zwave_js_server").getEffectiveLevel() == logging.INFO + client.async_send_command.reset_mock() + await hass.services.async_call( + LOGGER_DOMAIN, SERVICE_SET_LEVEL, {"zwave_js_server": "debug"}, blocking=True + ) + await hass.async_block_till_done() + assert logging.getLogger("zwave_js_server").getEffectiveLevel() == logging.DEBUG + + # Validate that the server logging was enabled + assert len(client.async_send_command.call_args_list) == 1 + assert client.async_send_command.call_args[0][0] == { + "command": "driver.update_log_config", + "config": {"level": "debug"}, + } + assert client.enable_server_logging.called + assert not client.disable_server_logging.called + + _reset_mocks() + + # Emulate server by setting log level to debug + event = Event( + type="log config updated", + data={ + "source": "driver", + "event": "log config updated", + "config": { + "enabled": False, + "level": "debug", + "logToFile": True, + "filename": "test", + "forceConsole": True, + }, + }, + ) + client.driver.receive_event(event) + + # "Enable" server logging and unload the entry + client.server_logging_enabled = True + await hass.config_entries.async_unload(entry.entry_id) + + # Validate that the server logging was disabled + assert len(client.async_send_command.call_args_list) == 1 + assert client.async_send_command.call_args[0][0] == { + "command": "driver.update_log_config", + "config": {"level": "info"}, + } + assert not client.enable_server_logging.called + assert client.disable_server_logging.called + + _reset_mocks() + + # Validate that the server logging doesn't get enabled because HA thinks it already + # is enabled + await hass.config_entries.async_setup(entry.entry_id) + await hass.async_block_till_done() + assert len(client.async_send_command.call_args_list) == 0 + assert not client.enable_server_logging.called + assert not client.disable_server_logging.called + + _reset_mocks() + + # "Disable" server logging and unload the entry + client.server_logging_enabled = False + await hass.config_entries.async_unload(entry.entry_id) + + # Validate that the server logging was not disabled because HA thinks it is already + # is disabled + assert len(client.async_send_command.call_args_list) == 0 + assert not client.enable_server_logging.called + assert not client.disable_server_logging.called