fix: logging, prediction update, multiple bugs (#584)

* Fix logging configuration issues that made logging stop operation. Switch to Loguru
  logging (from Python logging). Enable console and file logging with different log levels.
  Add logging documentation.

* Fix logging configuration and EOS configuration out of sync. Added tracking support
  for nested value updates of Pydantic models. This used to update the logging configuration
  when the EOS configurationm for logging is changed. Should keep logging config and EOS
  config in sync as long as all changes to the EOS logging configuration are done by
  set_nested_value(), which is the case for the REST API.

* Fix energy management task looping endlessly after the second update when trying to update
  the last_update datetime.

* Fix get_nested_value() to correctly take values from the dicts in a Pydantic model instance.

* Fix usage of model classes instead of model instances in nested value access when evaluation
  the value type that is associated to each key.

* Fix illegal json format in prediction documentation for PVForecastAkkudoktor provider.

* Fix documentation qirks and add EOS Connect to integrations.

* Support deprecated fields in configuration in documentation generation and EOSdash.

* Enhance EOSdash demo to show BrightSky humidity data (that is often missing)

* Update documentation reference to German EOS installation videos.

Signed-off-by: Bobby Noelte <b0661n0e17e@gmail.com>

tests/conftest.py

@@ -16,35 +16,75 @@ import pendulum
 import psutil
 import pytest
 import requests
+from _pytest.logging import LogCaptureFixture
+from loguru import logger
 from xprocess import ProcessStarter, XProcess
 
 from akkudoktoreos.config.config import ConfigEOS, get_config
-from akkudoktoreos.core.logging import get_logger
 from akkudoktoreos.server.server import get_default_host
 
-logger = get_logger(__name__)
+# -----------------------------------------------
+# Adapt pytest logging handling to Loguru logging
+# -----------------------------------------------
+
+@pytest.fixture
+def caplog(caplog: LogCaptureFixture):
+    """Propagate Loguru logs to the pytest caplog handler."""
+    handler_id = logger.add(
+        caplog.handler,
+        format="{message}",
+        level=0,
+        filter=lambda record: record["level"].no >= caplog.handler.level,
+        enqueue=False,  # Set to 'True' if your test is spawning child processes.
+    )
+    yield caplog
+    try:
+        logger.remove(handler_id)
+    except:
+        # May already be deleted
+        pass
+
+
+@pytest.fixture
+def reportlog(pytestconfig):
+    """Propagate Loguru logs to the pytest terminal reporter."""
+    logging_plugin = pytestconfig.pluginmanager.getplugin("logging-plugin")
+    handler_id = logger.add(logging_plugin.report_handler, format="{message}")
+    yield
+    try:
+        logger.remove(handler_id)
+    except:
+        # May already be deleted
+        pass
+
+
+@pytest.fixture(autouse=True)
+def propagate_logs():
+    """Deal with the pytest --log-cli-level command-line flag.
+
+    This option controls the standard logging logs, not loguru ones.
+    For this reason, we first install a PropagateHandler for compatibility.
+    """
+    class PropagateHandler(logging.Handler):
+        def emit(self, record):
+            if logging.getLogger(record.name).isEnabledFor(record.levelno):
+                logging.getLogger(record.name).handle(record)
+
+    logger.remove()
+    logger.add(PropagateHandler(), format="{message}")
+    yield
 
 
 @pytest.fixture()
 def disable_debug_logging(scope="session", autouse=True):
     """Automatically disable debug logging for all tests."""
-    original_levels = {}
-    root_logger = logging.getLogger()
+    logger.remove()  # Remove all loggers
+    logger.add(sys.stderr, level="INFO")  # Only show INFO and above
 
-    original_levels[root_logger] = root_logger.level
-    root_logger.setLevel(logging.INFO)
-
-    for logger_name, logger in logging.root.manager.loggerDict.items():
-        if isinstance(logger, logging.Logger):
-            original_levels[logger] = logger.level
-            if logger.level <= logging.DEBUG:
-                logger.setLevel(logging.INFO)
-
-    yield
-
-    for logger, level in original_levels.items():
-        logger.setLevel(level)
 
+# -----------------------------------------------
+# Provide pytest options for specific test setups
+# -----------------------------------------------
 
 def pytest_addoption(parser):
     parser.addoption(
@@ -144,6 +184,7 @@ def cfg_non_existent(request):
 
 @pytest.fixture(autouse=True)
 def user_cwd(config_default_dirs):
+    """Patch cwd provided by module pathlib.Path.cwd."""
     with patch(
         "pathlib.Path.cwd",
         return_value=config_default_dirs[1],
@@ -153,6 +194,7 @@ def user_cwd(config_default_dirs):
 
 @pytest.fixture(autouse=True)
 def user_config_dir(config_default_dirs):
+    """Patch user_config_dir provided by module platformdirs."""
     with patch(
         "akkudoktoreos.config.config.user_config_dir",
         return_value=str(config_default_dirs[0]),
@@ -162,6 +204,7 @@ def user_config_dir(config_default_dirs):
 
 @pytest.fixture(autouse=True)
 def user_data_dir(config_default_dirs):
+    """Patch user_data_dir provided by module platformdirs."""
     with patch(
         "akkudoktoreos.config.config.user_data_dir",
         return_value=str(config_default_dirs[-1] / "data"),
@@ -189,14 +232,18 @@ def config_eos(
     config_file_cwd = config_default_dirs[1] / ConfigEOS.CONFIG_FILE_NAME
     assert not config_file.exists()
     assert not config_file_cwd.exists()
+
     config_eos = get_config()
     config_eos.reset_settings()
     assert config_file == config_eos.general.config_file_path
     assert config_file.exists()
     assert not config_file_cwd.exists()
+
+    # Check user data directory pathes (config_default_dirs[-1] == data_default_dir_user)
     assert config_default_dirs[-1] / "data" == config_eos.general.data_folder_path
     assert config_default_dirs[-1] / "data/cache" == config_eos.cache.path()
     assert config_default_dirs[-1] / "data/output" == config_eos.general.data_output_path
+    assert config_default_dirs[-1] / "data/output/eos.log" == config_eos.logging.file_path
     return config_eos
 
 

tests/test_config.py

@@ -4,12 +4,10 @@ from typing import Union
 from unittest.mock import patch
 
 import pytest
+from loguru import logger
 from pydantic import ValidationError
 
 from akkudoktoreos.config.config import ConfigEOS, GeneralSettings
-from akkudoktoreos.core.logging import get_logger
-
-logger = get_logger(__name__)
 
 
 # overwrite config_mixin fixture from conftest

tests/test_dataabc.py

@@ -156,7 +156,7 @@ class TestDataRecord:
         assert "data_value" in record_dict
         assert record_dict["data_value"] == 20.0
         record2 = DerivedRecord.from_dict(record_dict)
-        assert record2 == record
+        assert record2.model_dump() == record.model_dump()
 
     def test_to_json(self):
         record = self.create_test_record(datetime(2024, 1, 3, tzinfo=timezone.utc), 10.0)
@@ -165,7 +165,7 @@ class TestDataRecord:
         assert "data_value" in json_str
         assert "20.0" in json_str
         record2 = DerivedRecord.from_json(json_str)
-        assert record2 == record
+        assert record2.model_dump() == record.model_dump()
 
 
 class TestDataSequence:
@@ -526,7 +526,7 @@ class TestDataSequence:
         data_dict = sequence.to_dict()
         assert isinstance(data_dict, dict)
         sequence_other = sequence.from_dict(data_dict)
-        assert sequence_other == sequence
+        assert sequence_other.model_dump() == sequence.model_dump()
 
     def test_to_json(self, sequence):
         record = self.create_test_record(datetime(2023, 11, 6), 0.8)

tests/test_elecpriceakkudoktor.py

@@ -5,10 +5,10 @@ from unittest.mock import Mock, patch
 import numpy as np
 import pytest
 import requests
+from loguru import logger
 
 from akkudoktoreos.core.cache import CacheFileStore
 from akkudoktoreos.core.ems import get_ems
-from akkudoktoreos.core.logging import get_logger
 from akkudoktoreos.prediction.elecpriceakkudoktor import (
     AkkudoktorElecPrice,
     AkkudoktorElecPriceValue,
@@ -22,8 +22,6 @@ FILE_TESTDATA_ELECPRICEAKKUDOKTOR_1_JSON = DIR_TESTDATA.joinpath(
     "elecpriceforecast_akkudoktor_1.json"
 )
 
-logger = get_logger(__name__)
-
 
 @pytest.fixture
 def provider(monkeypatch, config_eos):
@@ -94,7 +92,7 @@ def test_request_forecast(mock_get, provider, sample_akkudoktor_1_json):
     akkudoktor_data = provider._request_forecast()
 
     assert isinstance(akkudoktor_data, AkkudoktorElecPrice)
-    assert akkudoktor_data.values[0] == AkkudoktorElecPriceValue(
+    assert akkudoktor_data.values[0].model_dump() == AkkudoktorElecPriceValue(
         start_timestamp=1733785200000,
         end_timestamp=1733788800000,
         start="2024-12-09T23:00:00.000Z",
@@ -102,7 +100,7 @@ def test_request_forecast(mock_get, provider, sample_akkudoktor_1_json):
         marketprice=92.85,
         unit="Eur/MWh",
         marketpriceEurocentPerKWh=9.29,
-    )
+    ).model_dump()
 
 
 @patch("requests.get")

tests/test_logging.py

@@ -1,69 +1,35 @@
 """Test Module for logging Module."""
-
 import logging
-from logging.handlers import RotatingFileHandler
+import os
+import sys
 from pathlib import Path
+from unittest.mock import patch
 
 import pytest
+from loguru import logger
 
-from akkudoktoreos.core.logging import get_logger
+from akkudoktoreos.core.logging import track_logging_config
 
 # -----------------------------
-# get_logger
+# logsettings
 # -----------------------------
 
+class TestLoggingCommonSettings:
+    def teardown_method(self):
+        """Reset Loguru after each test to avoid handler contamination."""
+        logger.remove()
 
-def test_get_logger_console_logging():
-    """Test logger creation with console logging."""
-    logger = get_logger("test_logger", logging_level="DEBUG")
+    def test_valid_console_level_sets_logging(self, config_eos, caplog):
+        config_eos.track_nested_value("/logging", track_logging_config)
+        config_eos.set_nested_value("/logging/console_level", "INFO")
+        assert config_eos.get_nested_value("/logging/console_level") == "INFO"
+        assert config_eos.logging.console_level == "INFO"
+        assert any("console: INFO" in message for message in caplog.messages)
 
-    # Check logger name
-    assert logger.name == "test_logger"
-
-    # Check logger level
-    assert logger.level == logging.DEBUG
-
-    # Check console handler is present
-    assert len(logger.handlers) == 1
-    assert isinstance(logger.handlers[0], logging.StreamHandler)
-
-
-def test_get_logger_file_logging(tmpdir):
-    """Test logger creation with file logging."""
-    log_file = Path(tmpdir).joinpath("test.log")
-    logger = get_logger("test_logger", log_file=str(log_file), logging_level="WARNING")
-
-    # Check logger name
-    assert logger.name == "test_logger"
-
-    # Check logger level
-    assert logger.level == logging.WARNING
-
-    # Check console handler is present
-    assert len(logger.handlers) == 2  # One for console and one for file
-    assert isinstance(logger.handlers[0], logging.StreamHandler)
-    assert isinstance(logger.handlers[1], RotatingFileHandler)
-
-    # Check file existence
-    assert log_file.exists()
-
-
-def test_get_logger_no_file_logging():
-    """Test logger creation without file logging."""
-    logger = get_logger("test_logger")
-
-    # Check logger name
-    assert logger.name == "test_logger"
-
-    # Check logger level
-    assert logger.level == logging.INFO
-
-    # Check no file handler is present
-    assert len(logger.handlers) >= 1  # First is console handler (maybe be pytest handler)
-    assert isinstance(logger.handlers[0], logging.StreamHandler)
-
-
-def test_get_logger_with_invalid_level():
-    """Test logger creation with an invalid logging level."""
-    with pytest.raises(ValueError, match="Unknown loggin level: INVALID"):
-        logger = get_logger("test_logger", logging_level="INVALID")
+    def test_valid_console_level_calls_tracking_callback(self, config_eos):
+        with patch("akkudoktoreos.core.logging.track_logging_config") as mock_setup:
+            config_eos.track_nested_value("/logging", mock_setup)
+            config_eos.set_nested_value("/logging/console_level", "INFO")
+            assert config_eos.get_nested_value("/logging/console_level") == "INFO"
+            assert config_eos.logging.console_level == "INFO"
+            mock_setup.assert_called_once()

tests/test_pvforecastakkudoktor.py

@@ -3,9 +3,9 @@ from pathlib import Path
 from unittest.mock import Mock, patch
 
 import pytest
+from loguru import logger
 
 from akkudoktoreos.core.ems import get_ems
-from akkudoktoreos.core.logging import get_logger
 from akkudoktoreos.prediction.prediction import get_prediction
 from akkudoktoreos.prediction.pvforecastakkudoktor import (
     AkkudoktorForecastHorizon,
@@ -24,8 +24,6 @@ FILE_TESTDATA_PV_FORECAST_INPUT_SINGLE_PLANE = DIR_TESTDATA.joinpath(
 )
 FILE_TESTDATA_PV_FORECAST_RESULT_1 = DIR_TESTDATA.joinpath("pv_forecast_result_1.txt")
 
-logger = get_logger(__name__)
-
 
 @pytest.fixture
 def sample_settings(config_eos):

tests/test_pydantic.py

@@ -66,6 +66,11 @@ class TestPydanticModelNestedValueMixin:
         with pytest.raises(TypeError):
             PydanticModelNestedValueMixin._get_key_types(User, "unknown_field")
 
+    def test_get_key_types_for_instance_raises(self, user_instance):
+        """Test _get_key_types raises an error for an instance."""
+        with pytest.raises(TypeError):
+            PydanticModelNestedValueMixin._get_key_types(user_instance, "unknown_field")
+
     def test_set_nested_value_in_model(self, user_instance):
         """Test setting nested value in a model field (Address -> city)."""
         assert user_instance.addresses is None
@@ -123,7 +128,7 @@ class TestPydanticModelNestedValueMixin:
         """Test attempting to set value for a non-existent field."""
         user = User(name="John")
 
-        with pytest.raises(ValueError):
+        with pytest.raises(TypeError):
             user.set_nested_value("non_existent_field", "Some Value")
 
     def test_set_nested_value_with_invalid_type(self, user_instance):
@@ -144,6 +149,91 @@ class TestPydanticModelNestedValueMixin:
             "The first address should be an instance of Address"
         )
 
+    def test_track_nested_value_simple_callback(self, user_instance):
+        user_instance.set_nested_value("addresses/0/city", "NY")
+        assert user_instance.addresses is not None
+        assert user_instance.addresses[0].city == "NY"
+
+        callback_calls = []
+        def cb(model, path, old, new):
+            callback_calls.append((path, old, new))
+
+        user_instance.track_nested_value("addresses/0/city", cb)
+        user_instance.set_nested_value("addresses/0/city", "LA")
+        assert user_instance.addresses is not None
+        assert user_instance.addresses[0].city == "LA"
+        assert callback_calls == [("addresses/0/city", "NY", "LA")]
+
+    def test_track_nested_value_prefix_triggers(self, user_instance):
+        user_instance.set_nested_value("addresses/0", Address(city="Berlin", postal_code="10000"))
+        assert user_instance.addresses is not None
+        assert user_instance.addresses[0].city == "Berlin"
+
+        cb_prefix = []
+        cb_exact = []
+
+        def cb1(model, path, old, new):
+            cb_prefix.append((path, old, new))
+        def cb2(model, path, old, new):
+            cb_exact.append((path, old, new))
+
+        user_instance.track_nested_value("addresses/0", cb1)
+        user_instance.track_nested_value("addresses/0/city", cb2)
+        user_instance.set_nested_value("addresses/0/city", "Munich")
+        assert user_instance.addresses is not None
+        assert user_instance.addresses[0].city == "Munich"
+
+        # Both callbacks should be triggered
+        assert cb_prefix == [("addresses/0/city", "Berlin", "Munich")]
+        assert cb_exact == [("addresses/0/city", "Berlin", "Munich")]
+
+    def test_track_nested_value_multiple_callbacks_same_path(self, user_instance):
+        user_instance.set_nested_value("addresses/0/city", "Berlin")
+        calls1 = []
+        calls2 = []
+
+        user_instance.track_nested_value("addresses/0/city", lambda lib, path, o, n: calls1.append((path, o, n)))
+        user_instance.track_nested_value("addresses/0/city", lambda lib, path, o, n: calls2.append((path, o, n)))
+        user_instance.set_nested_value("addresses/0/city", "Stuttgart")
+
+        assert calls1 == [("addresses/0/city", "Berlin", "Stuttgart")]
+        assert calls2 == [("addresses/0/city", "Berlin", "Stuttgart")]
+
+    def test_track_nested_value_invalid_path_raises(self, user_instance):
+        with pytest.raises(ValueError) as excinfo:
+            user_instance.track_nested_value("unknown_field", lambda model, path, o, n: None)
+        assert "is invalid" in str(excinfo.value)
+
+        with pytest.raises(ValueError) as excinfo:
+            user_instance.track_nested_value("unknown_field/0/city", lambda model, path, o, n: None)
+        assert "is invalid" in str(excinfo.value)
+
+    def test_track_nested_value_list_and_dict_path(self):
+        class Book(PydanticBaseModel):
+            title: str
+
+        class Library(PydanticBaseModel):
+            books: list[Book]
+            meta: dict[str, str] = {}
+
+        lib = Library(books=[Book(title="A")], meta={"location": "center"})
+        assert lib.meta["location"] == "center"
+        calls = []
+
+        # For list, only root attribute structure is checked, not indices
+        lib.track_nested_value("books/0/title", lambda lib, path, o, n: calls.append((path, o, n)))
+        lib.set_nested_value("books/0/title", "B")
+        assert lib.books[0].title == "B"
+        assert calls == [("books/0/title", "A", "B")]
+
+        # For dict, only root attribute structure is checked
+        meta_calls = []
+        lib.track_nested_value("meta/location", lambda lib, path, o, n: meta_calls.append((path, o, n)))
+        assert lib.meta["location"] == "center"
+        lib.set_nested_value("meta/location", "north")
+        assert lib.meta["location"] == "north"
+        assert meta_calls == [("meta/location", "center", "north")]
+
 
 class TestPydanticBaseModel:
     def test_valid_pendulum_datetime(self):