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

@@ -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)
 

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)

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

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
+async def async_enable_server_logging_if_needed(
-def async_update_data_collection_preference(
+    hass: HomeAssistant, entry: ConfigEntry, driver: Driver
-    hass: HomeAssistant, entry: ConfigEntry, preference: bool
 ) -> None:
-    """Update data collection preference on config entry."""
+    """Enable logging of zwave-js-server in the lib."""
-    new_data = entry.data.copy()
+    # If lib log level is set to debug, we want to enable server logging. First we
-    new_data[CONF_DATA_COLLECTION_OPTED_IN] = preference
+    # check if server log level is less verbose than library logging, and if so, set it
-    hass.config_entries.async_update_entry(entry, data=new_data)
+    # 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:

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",

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

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