From de496509a9e7e4e96d38311ef65ba745b9e2e4fd Mon Sep 17 00:00:00 2001
From: John Lancaster <32917998+jsl12@users.noreply.github.com>
Date: Mon, 21 Oct 2024 03:15:59 +0000
Subject: [PATCH] WIP

---
 appdaemon/context_manager.py | 14 ++++++++------
 appdaemon/main.py            |  6 ++++--
 appdaemon/subsystem.py       | 20 ++++++++++++++------
 3 files changed, 26 insertions(+), 14 deletions(-)

diff --git a/appdaemon/context_manager.py b/appdaemon/context_manager.py
index 4498b4a..723df27 100644
--- a/appdaemon/context_manager.py
+++ b/appdaemon/context_manager.py
@@ -15,7 +15,7 @@ logger = logging.getLogger(__name__)
 class AppDaemonRunContext:
     _stack: ExitStack = field(default_factory=ExitStack)
     stop_event: Event = field(default_factory=Event)
-    shutdown_grace_period: float = 0.75
+    shutdown_grace_period: float = 0.1
 
     loop: asyncio.AbstractEventLoop = field(init=False)
     executor: ThreadPoolExecutor = field(init=False)
@@ -37,10 +37,10 @@ class AppDaemonRunContext:
         logger.debug(f'Closing context from {self.__class__.__name__}')
         self._stack.close()
 
-    def get_running_tasks(self, exclude_current: bool = True) -> list[asyncio.Task]:
+    def get_running_tasks(self) -> list[asyncio.Task]:
         return [
             t for t in asyncio.all_tasks(self.loop)
-            if exclude_current and t is not asyncio.current_task()
+            if t is not asyncio.current_task()
         ]
 
     async def shutdown(self, signal=signal.SIGTERM):
@@ -59,15 +59,17 @@ class AppDaemonRunContext:
                 asyncio.wait_for(t, timeout=self.shutdown_grace_period)
                 for t in tasks
             )
-            logger.debug(f'Allowing graceful shutdown from stop event for {
-                         self.shutdown_grace_period}s')
+            logger.debug(
+                'Allowing graceful shutdown from stop event for %ss',
+                self.shutdown_grace_period
+            )
             await asyncio.gather(*graceful, return_exceptions=True)
 
             for task in tasks:
                 if task.cancelled():
                     logger.warning(f'Cancelled {task.get_name()}')
 
-            logger.info("Stopping asyncio event loop")
+            logger.info("Calling stop() for asyncio event loop")
             self.loop.stop()
         else:
             logger.warning('Already started shutdown')
diff --git a/appdaemon/main.py b/appdaemon/main.py
index bc78c0c..32bb252 100644
--- a/appdaemon/main.py
+++ b/appdaemon/main.py
@@ -43,6 +43,7 @@ class ADMain:
         if hasattr(self, 'ad'):
             self.ad.logger.info('Running asyncio event loop indefinitely...')
             self.run_context.loop.run_forever()
+            self.ad.logger.debug('Gracefully stopped event loop')
         else:
             logging.error('Running ADMain without context manager')
 
@@ -59,7 +60,7 @@ if __name__ == '__main__':
         {
             'version': 1,
             'disable_existing_loggers': False,
-            'formatters': {'basic': {'style': '{', 'format': '[yellow]{name}[/] {message}'}},
+            'formatters': {'basic': {'style': '{', 'format': '[yellow]{name:20}[/] {message}'}},
             'handlers': {
                 'rich': {
                     '()': 'rich.logging.RichHandler',
@@ -69,9 +70,10 @@ if __name__ == '__main__':
                     'markup': True
                 }
             },
-            'root': {'level': 'INFO', 'handlers': ['rich']},
+            'root': {'level': 'DEBUG', 'handlers': ['rich']},
         }
     )
 
     with ADMain('/conf/ad-test/conf/appdaemon.yaml') as main:
         main.run()
+        main.ad.logger.debug('Exiting main context from with statement')
diff --git a/appdaemon/subsystem.py b/appdaemon/subsystem.py
index 34db7a8..6df0e99 100644
--- a/appdaemon/subsystem.py
+++ b/appdaemon/subsystem.py
@@ -34,40 +34,46 @@ class ADSubsystem:
         self.logger.debug(f'Starting {self.__class__.__name__}')
 
     def __exit__(self, exc_type, exc_value, traceback):
-        self.logger.debug(f'Exiting {self.__class__.__name__}')
+        pass
+        # self.logger.debug(f'Exiting {self.__class__.__name__}')
 
     @property
     def stopping(self) -> bool:
         return self.stop.is_set()
 
     async def sleep(self, delay: float):
+        """Wrapper function for asyncio.sleep that suppresses and logs a task cancellation"""
         try:
             if not self.stopping:
                 await asyncio.sleep(delay)
+            else:
+                self.logger.debug('Skipping sleep due to stop event')
         except asyncio.CancelledError:
             self.logger.debug('Cancelled during sleep')
 
 
 @dataclass
 class Utility(ADSubsystem):
-    loop_rate: float = 0.25
+    loop_rate: float = 1.0
 
     def __enter__(self):
         super().__enter__()
-        self.create_task(self.loop(), 'Utility loop', critical=True)
+        self.create_task(self.loop(), 'utility loop', critical=True)
         return self
 
     async def loop(self):
         while not self.stopping:
             self.logger.debug('Looping...')
             await self.sleep(self.loop_rate)
-        self.logger.debug('Stopped utility loop gracefully')
+        
+        task_name = asyncio.current_task().get_name()
+        self.logger.debug(f'Gracefully stopped {task_name} task')
 
 
 @dataclass
 class Plugin(ADSubsystem):
     state: dict[str, int] = field(default_factory=dict)
-    update_rate: float = 2.0
+    update_rate: float = 5.0
 
     def __post_init__(self) -> None:
         super().__post_init__()
@@ -100,7 +106,9 @@ class Plugin(ADSubsystem):
                 #     raise ValueError('fake error')
 
             await self.sleep(self.update_rate)
-        self.logger.debug('Stopped plugin updates gracefully')
+        
+        task_name = asyncio.current_task().get_name()
+        self.logger.debug(f'Gracefully stopped {task_name} task')
 
 
 @dataclass