Merge pull request #125 from cyiallou/task/add-logger

Add consistent logger setup across all modules

Author: cyiallou

RELEASE_NOTES.md

@@ -10,7 +10,7 @@
 
 ## New Features
 
-<!-- Here goes the main new features and examples or instructions on how to use them -->
+- Added consistent logger setup across all modules for structured logging and improved observability. Example notebooks updated to demonstrate logger usage.
 
 ## Bug Fixes
 

examples/Alerts Notebook.ipynb

@@ -83,11 +83,12 @@
   },
   {
    "cell_type": "code",
-   "execution_count": 1,
+   "execution_count": null,
    "metadata": {},
    "outputs": [],
    "source": [
     "import datetime\n",
+    "import logging\n",
     "import os\n",
     "from dataclasses import asdict, dataclass, field\n",
     "\n",
@@ -98,28 +99,32 @@
   },
   {
    "cell_type": "code",
-   "execution_count": 2,
+   "execution_count": null,
    "metadata": {},
-   "outputs": [
-    {
-     "data": {
-      "text/plain": [
-       "True"
-      ]
-     },
-     "execution_count": 2,
-     "metadata": {},
-     "output_type": "execute_result"
-    }
-   ],
+   "outputs": [],
+   "source": [
+    "logging.basicConfig(\n",
+    "    level=logging.WARNING,\n",
+    "    format=\"%(asctime)s %(levelname)s %(name)s: %(message)s\",\n",
+    "    datefmt=\"%H:%M:%S\",\n",
+    ")\n",
+    "logging.getLogger(\"matplotlib.font_manager\").setLevel(logging.ERROR)\n",
+    "logging.getLogger(\"frequenz.lib.notebooks\").setLevel(logging.WARNING)"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {},
+   "outputs": [],
    "source": [
     "# Load environment variables from the .env file\n",
     "load_dotenv()"
    ]
   },
   {
    "cell_type": "code",
-   "execution_count": 3,
+   "execution_count": null,
    "metadata": {},
    "outputs": [],
    "source": [
@@ -222,13 +227,13 @@
   },
   {
    "cell_type": "code",
-   "execution_count": 4,
+   "execution_count": null,
    "metadata": {},
    "outputs": [],
    "source": [
     "# example user request (1 year of data)\n",
     "end_time = datetime.datetime.now().astimezone(datetime.timezone.utc)\n",
-    "start_time = end_time - datetime.timedelta(days=364)\n",
+    "start_time = end_time - datetime.timedelta(days=14)\n",
     "\n",
     "USER_REQUEST = {\n",
     "    \"weather_service_address\": os.environ.get(\"WEATHER_SERVICE_ADDRESS\"),\n",
@@ -253,7 +258,7 @@
   },
   {
    "cell_type": "code",
-   "execution_count": 5,
+   "execution_count": null,
    "metadata": {},
    "outputs": [],
    "source": [

examples/Solar Maintenance.ipynb

@@ -75,7 +75,7 @@
 from types import UnionType
 from typing import Any, Callable, TypeVar, Union, get_args, get_origin
 
-_log = logging.getLogger(__name__)
+_logger = logging.getLogger(__name__)
 
 
 DataclassT = TypeVar("DataclassT", bound="FromDictMixin")
@@ -346,7 +346,7 @@ def start(self, task: Callable[..., None], **kwargs: Any) -> None:
         """
         self.task = task
         self._task_name = task.__name__
-        _log.info(
+        _logger.info(
             "Starting scheduler for task '%s' to execute every %d seconds and %s",
             self._task_name,
             self._config.interval,
@@ -365,18 +365,18 @@ def stop(self) -> None:
         """Stop the scheduler."""
         if self._thread is not None:
             if self._thread.is_alive():
-                _log.info("Stopping scheduler for task '%s'", self._task_name)
+                _logger.info("Stopping scheduler for task '%s'", self._task_name)
                 self._stop_event.set()
                 if not self._stop_event.is_set():
-                    _log.error(
+                    _logger.error(
                         "Failed to stop scheduler for task '%s'", self._task_name
                     )
         else:
-            _log.warning(
+            _logger.warning(
                 "Attempted to stop scheduler for task '%s', but no active thread was found.",
                 self._task_name,
             )
-        _log.info("Scheduler successfully stopped")
+        _logger.info("Scheduler successfully stopped")
 
     def _run_task(self, kwargs: dict[str, Any]) -> None:
         """Run the scheduled task.
@@ -389,19 +389,21 @@ def _run_task(self, kwargs: dict[str, Any]) -> None:
             elapsed = self._execute_task(kwargs)
             self._pace(elapsed)
         else:
-            _log.info(
+            _logger.info(
                 "Waiting for first interval before sending the first notification."
             )
             self._pace(0)
         while not self._should_stop():
             elapsed = self._execute_task(kwargs)
             self._pace(elapsed)
-        _log.info("Scheduler stopping: stop condition met.")
+        _logger.info("Scheduler stopping: stop condition met.")
         self.stop()
 
     def _should_stop(self) -> bool:
         """Return True if the scheduler should stop."""
-        _log.debug("Checking if scheduler for task '%s' should stop.", self._task_name)
+        _logger.debug(
+            "Checking if scheduler for task '%s' should stop.", self._task_name
+        )
         return self._stop_event.is_set() or (
             self._config.duration is not None
             and self._start_time is not None
@@ -422,14 +424,14 @@ def _execute_task(self, kwargs: dict[str, Any]) -> float:
             if self.task:
                 self.task(**kwargs)
         except Exception as e:  # pylint: disable=broad-except
-            _log.error(
+            _logger.error(
                 "Error occurred during scheduled execution of %s: %s",
                 self._task_name,
                 e,
             )
         finally:
             task_elapsed = time.time() - task_start_time
-            _log.debug(
+            _logger.debug(
                 "Execution of task '%s' completed in %.2f seconds.",
                 self._task_name,
                 task_elapsed,
@@ -465,7 +467,9 @@ def _pace(self, elapsed_task_time: float) -> None:
             actual_sleep = max(0, sleep_duration - elapsed_task_time)
         if self._stop_event.is_set():
             return
-        _log.info("Sleeping for %.2f seconds before next task execution.", actual_sleep)
+        _logger.info(
+            "Sleeping for %.2f seconds before next task execution.", actual_sleep
+        )
         self._stop_event.wait(actual_sleep)
 
 
@@ -503,15 +507,17 @@ def send_with_retry(
         for attempt in range(retries + 1):
             try:
                 send_func(**kwargs)
-                _log.info("Successfully sent notification on attempt %d", attempt + 1)
+                _logger.info(
+                    "Successfully sent notification on attempt %d", attempt + 1
+                )
                 return
             except Exception as e:  # pylint: disable=broad-except
                 last_exception = e
-                _log.error("Attempt %d failed: %s", attempt + 1, e)
+                _logger.error("Attempt %d failed: %s", attempt + 1, e)
                 if attempt < retries - 1:
                     linear_backoff = backoff_factor * (attempt + 1)
                     time.sleep(min(max_sleep, linear_backoff))
-        _log.error("Failed to send notification after %d retries", retries)
+        _logger.error("Failed to send notification after %d retries", retries)
         raise NotificationSendError(
             "Notification failed after all retry attempts.",
             last_exception=last_exception,
@@ -520,17 +526,17 @@ def send_with_retry(
     def start_scheduler(self) -> None:
         """Start the scheduler if configured."""
         if self._scheduler:
-            _log.info("Starting scheduler for %s", self.__class__.__name__)
+            _logger.info("Starting scheduler for %s", self.__class__.__name__)
             self._scheduler.start(self.send)
         else:
-            _log.warning("No scheduler config provided. Cannot start scheduler.")
+            _logger.warning("No scheduler config provided. Cannot start scheduler.")
 
     def stop_scheduler(self) -> None:
         """Stop the running scheduler."""
         if not self._scheduler:
-            _log.warning("No active scheduler to stop.")
+            _logger.warning("No active scheduler to stop.")
             return
-        _log.info("Stopping scheduler for notification: %s", self.__class__.__name__)
+        _logger.info("Stopping scheduler for notification: %s", self.__class__.__name__)
         self._scheduler.stop()
 
     @abstractmethod
@@ -559,7 +565,7 @@ def __init__(self, config: EmailConfig) -> None:
         super().__init__()
         self._config: EmailConfig = config
         if self._config.scheduler:
-            _log.debug(
+            _logger.debug(
                 "EmailNotification configured with scheduler: %s",
                 self._config.scheduler,
             )
@@ -625,9 +631,9 @@ def _attach_files(self, msg: EmailMessage, attachments: list[str]) -> None:
                     )
             except OSError as e:
                 failed_attachments.append(file)
-                _log.error("Failed to attach file %s: %s", file, e)
+                _logger.error("Failed to attach file %s: %s", file, e)
         if failed_attachments:
-            _log.warning(
+            _logger.warning(
                 "The following attachments could not be added: %s", failed_attachments
             )
 
@@ -676,9 +682,9 @@ def _connect_and_send(
                 server.starttls()
                 server.login(str(smtp_settings["user"]), str(smtp_settings["password"]))
                 server.send_message(msg)
-            _log.info("Email sent successfully to %s", to_emails)
+            _logger.info("Email sent successfully to %s", to_emails)
         except SMTPException as e:
-            _log.error("Failed to send email: %s", e)
+            _logger.error("Failed to send email: %s", e)
             raise
 
 

examples/solar_maintenance_example.ipynb

@@ -22,20 +22,19 @@
     NotificationSendError,
 )
 
-_log = logging.getLogger(__name__)
+_logger = logging.getLogger(__name__)
 
 EMAIL_REGEX = re.compile(r"^[^@\s]+@[^@\s]+\.[^@\s]+$")
 
 
-def send_test_email(config: EmailConfig, verbose: bool = True) -> bool:
+def send_test_email(config: EmailConfig) -> bool:
     """Send a test email using the given EmailConfig.
 
     The email message is generated automatically based on the provided
     configuration and replaces the provided one.
 
     Args:
         config: An EmailConfig instance.
-        verbose: If True, prints the result to stdout.
 
     Returns:
         True if the email was sent successfully, False otherwise.
@@ -75,19 +74,15 @@ def send_test_email(config: EmailConfig, verbose: bool = True) -> bool:
         email_notification = EmailNotification(config=config)
         email_notification.send()
         msg = "✅ Test email sent successfully!"
-        _log.info(msg)
-        if verbose:
-            print(msg)
+        _logger.info(msg)
         return True
     except NotificationSendError as e:
         msg = f"❌ Error sending test email: {e}"
-        _log.error(msg)
+        _logger.error(msg)
         if e.last_exception:
-            _log.debug(
+            _logger.debug(
                 "Traceback:\n%s", "".join(traceback.format_exception(e.last_exception))
             )
-        if verbose:
-            print(msg)
         return False