Add lots of logging

- Processes need a descriptive 'name' now
- Wait for process to fully die & be reaped before releasing lock
  in kill. Also set the running flag to False in kill - otherwise
  we wait for _restart_process_if_needed to be scheduled & called
  in the future before state is consistent.

simpervisor.py

@@ -2,11 +2,13 @@
 Simple asynchronous process supervisor
 """
 import asyncio
+import logging
 
 
 class SupervisedProcess:
-    def __init__(self, *args, always_restart=False, **kwargs):
+    def __init__(self, name, *args, always_restart=False, **kwargs):
         self.always_restart = always_restart
+        self.name = name
         self._proc_args = args
         self._proc_kwargs = kwargs
         self.proc: asyncio.Process = None
@@ -20,6 +22,19 @@ def __init__(self, *args, always_restart=False, **kwargs):
         # Only one coroutine should be starting or killing a process at a time
         self._start_stop_lock = asyncio.Lock()
 
+        self.log = logging.getLogger('simpervisor')
+
+    def _debug_log(self, action, message, extras=None):
+        base_extras = {
+            'action': action,
+            'proccess-name': self.name,
+            'process-args': self._proc_args,
+            'process-kwargs': self._proc_kwargs
+        }
+        if extras:
+            base_extras.update(extras)
+        self.log.debug(message, extra=base_extras)
+
     async def start(self):
         """
         Start the process
@@ -28,9 +43,12 @@ async def start(self):
             if self.running:
                 # Don't wanna start it again, if we're already running
                 return
+            self._debug_log('try-start', f'Trying to start {self.name}',)
             self.proc = await asyncio.create_subprocess_exec(
                 *self._proc_args, **self._proc_kwargs
             )
+            self._debug_log('started', f'Started {self.name}',)
+
         self._killed = False
         self.running = True
 
@@ -39,15 +57,26 @@ async def start(self):
 
     async def _restart_process_if_needed(self):
         retcode = await self.proc.wait()
+        self._debug_log(
+            'exited', f'{self.name} exited with code {retcode}',
+            {'code': retcode}
+        )
         self.running = False
         if (not self._killed) and (self.always_restart or retcode != 0):
             await self.start()
 
     async def kill(self):
         self._killed = True
         with (await self._start_stop_lock):
+            self._debug_log('killing', f'Killing {self.name}')
             self.proc.kill()
-        return await self.proc.wait()
+            retcode = await self.proc.wait()
+            self._debug_log(
+                'killed',
+                f'Killed {self.name}, with retcode {retcode}', extras={'code': retcode}
+            )
+            self.running = False
+        return retcode
 
     @property
     def pid(self):

test_simpervisor.py

@@ -1,6 +1,8 @@
+import inspect
 import asyncio
 import pytest
 import sys
+import logging
 
 import simpervisor
 
@@ -22,7 +24,7 @@ async def test_start_success():
     Start a process & check its running status
     """
     proc = simpervisor.SupervisedProcess(
-        *sleep(0), always_restart=False
+        inspect.currentframe().f_code.co_name, *sleep(0), always_restart=False
     )
     await proc.start()
     assert proc.running
@@ -35,7 +37,7 @@ async def test_start_always_restarting():
     Start a process & check it restarts even when it succeeds
     """
     proc = simpervisor.SupervisedProcess(
-        *sleep(0), always_restart=True
+        inspect.currentframe().f_code.co_name, *sleep(0), always_restart=True
     )
     await proc.start()
     assert proc.running
@@ -55,7 +57,7 @@ async def test_start_fail_restarting():
     Start a process that fails & make sure it restarts
     """
     proc = simpervisor.SupervisedProcess(
-        *sleep(1), always_restart=True
+        inspect.currentframe().f_code.co_name, *sleep(1), always_restart=True
     )
     await proc.start()
     assert proc.running
@@ -76,11 +78,14 @@ async def test_start_multiple_start():
     Starting the same process multiple times should be a noop
     """
     proc = simpervisor.SupervisedProcess(
-        *sleep(0), always_restart=True
+        inspect.currentframe().f_code.co_name, *sleep(0), always_restart=True
     )
     await proc.start()
     assert proc.running
     first_pid = proc.pid
     await proc.start()
     assert proc.running
     assert proc.pid == first_pid
+
+    await proc.kill()
+    assert not proc.running