Sheep compatiability (#21)

This PR will be merged when there is all of the parts which sheep needs
to run working.

.gitignore

@@ -149,4 +149,5 @@ usercode/editable/*
 !usercode/editable/main.py
 !usercode/editable/minimal_example.py
 !usercode/editable/snippests.py
-logs.txt
+logs.txt
+run.sh

app/logging.py

@@ -4,7 +4,7 @@
 from copy import copy
 import http
 
-_logger = logging.getLogger()
+logger = logging.getLogger("app")
 
 
 class CustomFormatter(logging.Formatter):
@@ -90,25 +90,30 @@ def format(self, record):
 
 
 def configure_logger(name: str, new_fomater, level):
+    """Applies `new_formater` to a logger specified by `name`
+    Ensure that this logger does not interfer with the root logger
+    Sets the loggers level to `level`
+    """
     logger = logging.getLogger(name)
     logger.propagate = False
     if len(logger.handlers) > 0:
         logger.handlers[0].setFormatter(new_fomater())
     logger.setLevel(level)
 
 
-def configure_logging(level=logging.DEBUG, uvicorn_level=logging.INFO):
+def configure_logging(level=logging.DEBUG, third_party_level=logging.INFO):
     """Apply the logging formatters to the logging handlers
     Prevents uvicorn's handlers from double logging
     Sets logging level to `level`
     `uvicorn_level` allows the shepherd logs to come through by raising the uvicorn level
     """
-    configure_logger("uvicorn", UvicornFormatter, uvicorn_level)
-    configure_logger("uvicorn.access", UvicornAccessFormatter, uvicorn_level)
+    configure_logger("uvicorn", UvicornFormatter, third_party_level)
+    configure_logger("uvicorn.access", UvicornAccessFormatter, third_party_level)
+    configure_logger("multipart", logging.Formatter, third_party_level)
 
-    _logger.setLevel(level)
+    logger.setLevel(level)
     ch = logging.StreamHandler()
     ch.setLevel(level)
     ch.setFormatter(ShepherdFormatter())
-    _logger.addHandler(ch)
-    _logger.info("Logging configured")
+    logger.addHandler(ch)
+    logger.info("Logging configured")

app/main.py

@@ -8,11 +8,12 @@
 from app.run import runner
 from app.config import config
 from app.upload import increase_max_file_size
-from app.logging import configure_logging
+from app.logging import configure_logging, logger
 
 
 configure_logging()
 
+
 shepherd = FastAPI(
     title="Shepherd",
     version="0.0.1",
@@ -32,14 +33,15 @@
 @shepherd.on_event("startup")
 def startup_event():
     """Setup which is run before the rest of shepherd.
-
+    This works a round bugs in python. See doc string of `increase_max_file_size`
     """
     increase_max_file_size()
 
 
 @shepherd.on_event("shutdown")
 def shutdown_event():
     """Kill any running usercode"""
+    logger.info("Shutting down usercode forcing may leave usercode still running")
     runner.shutdown()
     if os.path.exists(config.usr_fifo_path) is True:
         os.remove(config.usr_fifo_path)

app/run.py

@@ -2,20 +2,16 @@
 import errno
 import io
 import os
-from sre_parse import State
 import subprocess as sp
 import threading
 import sys
 import time
 from enum import Enum
 
-import logging
-
+from app.logging import logger
 from app.config import config
 
 
-_logger = logging.getLogger(__name__)
-
 class States(Enum):
     INIT = "Init"
     RUNNING = "Running"
@@ -44,11 +40,11 @@ def __init__(self):
         self.state_transition_lock = threading.Lock()
         self.new_state_event = threading.Event()
         self.new_state_event.set()
-        self.runner = threading.Thread(target=self._state_machine, daemon=True)
         self.watchdog = threading.Thread(
             target=self._run_watchdog, daemon=True)
-        self.runner.start()
+        self.runner = threading.Thread(target=self._state_machine, daemon=True)
         self.watchdog.start()
+        self.runner.start()
 
     def _enter_init_state(self) -> None:
         """Start the user process running.
@@ -69,7 +65,7 @@ def _enter_init_state(self) -> None:
             env=config.robot_env,
             preexec_fn=os.setsid
         )
-        logging.info(f"Started usercode PID:{os.getpgid(self.user_sp.pid)}")
+        logger.info(f"Started usercode PID:{os.getpgid(self.user_sp.pid)}")
 
     def _enter_running_state(self) -> None:
         """Send start signal to usercode"""
@@ -88,49 +84,32 @@ def _enter_running_state(self) -> None:
     def _enter_stopped_state(self) -> None:
         """Reap the users code"""
         if self.user_sp is None:
+            logger.debug("Re-entering STOPPED state. Usercode already stopped")
             return
         return_code = self.user_sp.poll()
         if return_code is None:
-            logging.info("Usercode is still running but we need to kill it")
-            # User code is still running so we need to kill it
-            try:
-                try:
-                    logging.info(f"Sending terminate signal to {self.user_sp.pid}")
-                    self.user_sp.terminate()
-                    logging.info("Sent terminate signal")
-                    self.user_sp.communicate(timeout=config.reap_grace_time)
-                    logging.info("Usercode terminated")
-                except sp.TimeoutExpired:
-                    logging.warning(
-                        f"Usercode could not be terminated within {config.reap_grace_time}s "
-                         "sending kill signal"
-                    )
-                    self.user_sp.kill()
-                    self.user_sp.communicate()
-            except OSError as e:
-                # Died between us seeing its alive and killing it
-                logging.warning(e)
-                if e.errno != errno.ESRCH:
-                    raise e
-            logging.info("usercode stopped")
-        elif self._current_state == States.STOPPED:
-            logging.debug("Re-entering STOPPED state. Usercode already stopped")
+            self.kill_usercode()
         else:
-            logging.debug(
+            logger.debug(
                 f"Usercode exited with {return_code} but was not killed by Shepherd")
         self.output_file.close()
+        self.user_sp = None
 
     def _state_machine(self) -> None:
         """The lifecycle of the usercode
         Don't need a try/finally as main.shutdown handles forcing into STOPPED state
         """
         state_timeout = None
+        self._next_state = States.INIT
+        self._current_state = None
+
         while True:
             self.new_state_event.wait(timeout=state_timeout)
             with self.state_transition_lock:
                 self.new_state_event.clear()
-                _logger.info(
+                logger.info(
                     f"Moving state from {self._current_state} to {self._next_state}")
+                self._current_state = self._next_state
                 match self._next_state:
                     case States.INIT:
                         self._enter_init_state()
@@ -144,7 +123,6 @@ def _state_machine(self) -> None:
                         self._enter_stopped_state()
                         self._next_state = States.STOPPED
                         state_timeout = None
-                self._current_state = self._next_state
 
     @property
     def state(self) -> States:
@@ -163,6 +141,31 @@ def state(self, next_state: States) -> None:
         while self.new_state_event.is_set():  # Only cleared in the state_machine thread
             time.sleep(0.05)                  # Don't use 100% CPU
 
+    def kill_usercode(self):
+        """Try and terminate usercode if unable kill it.
+        This function deliberately does not acquire any lock on the state machine
+        and so the effect of this will only be noticed by the watchdog
+        """
+        logger.info("Trying to kill usercode")
+        if (self.user_sp is not None) and (self.user_sp is not None):
+            try:
+                try:
+                    self.user_sp.terminate()
+                    self.user_sp.communicate(timeout=config.reap_grace_time)
+                    logger.info("subprocess thinks usercode is dead")
+                except sp.TimeoutExpired:
+                    logger.warning(
+                        f"Usercode could not be terminated within {config.reap_grace_time}s "
+                            "sending kill signal"
+                    )
+                    self.user_sp.kill()
+                    self.user_sp.communicate()
+            except OSError as e:
+                # Usercode was already dead
+                if e.errno != errno.ESRCH:
+                    raise e
+
+
     def get_output(self):
         """Open the output file in reading text mode, line buffered"""
         if not self.output_file.closed:
@@ -180,13 +183,16 @@ def _run_watchdog(self) -> None:
             if self._current_state == States.RUNNING:  # Don't acquire lock unless we might need it
                 with self.state_transition_lock:
                     if (self._current_state == States.RUNNING) and (self.user_sp.poll() is not None):
-                        logging.info("WATCHDOG: Detected usercode has exited")
+                        logger.info("WATCHDOG: Detected usercode has exited")
                         self._next_state = States.STOPPED
                         self.new_state_event.set()
 
+
+
     def shutdown(self):
-        self.state = States.STOPPED
-        self.output_file.close()
+        self.kill_usercode()
+        if self.output_file is not None:
+            self.output_file.close()
 
 
 runner = Runner()

app/upload.py

@@ -12,14 +12,17 @@
 
 
 def _is_python(file: fastapi.UploadFile) -> bool:
+    """Returns if `file` is likely a python file"""
     return file.content_type.startswith("text") or file.filename.endswith(".py")
 
 
 def _is_zip(file: fastapi.UploadFile) -> bool:
+    """Returns if `file` is likely a zip"""
     return (("zip" in file.content_type) or file.filename.endswith(".zip"))
 
 
 def _stage_python(dir: tempfile.TemporaryDirectory, in_file: fastapi.UploadFile):
+    """Place a python `in_file` in `dir`"""
     entry_point = Path(dir.name) / config.round_entry_point
     with open(entry_point, 'wb') as out_file:
         content = in_file.file.read()
@@ -74,6 +77,7 @@ def increase_max_file_size():
 
 
 def _stage_zip(dir: tempfile.TemporaryDirectory, in_file: fastapi.UploadFile):
+    """Try and extract a zip `in_file` to `dir` and check it is a valid zip"""
     _fix_bad_spools(in_file)
 
     try:

install.sh

@@ -2,6 +2,10 @@
 
 echo "Running shepherd-2 installer"
 
+# Poetry needs these to run
+sudo apt-get install python3-distutils -y
+sudo apt-get install python3-apt -y
+
 if ! command -v poetry
 then
     echo "Poetry not found. Downloading and installing."
@@ -17,12 +21,12 @@ then
     fi
 fi
 
-# Can be used with --debug for hot reload
-touch run.sh
-echo "poetry run uvicorn app:app" > run.sh
 
 echo "installing python dependancies using poetry"
 if poetry install; then
+    # Can be used with --debug for hot reload
+    touch run.sh
+    echo "poetry run uvicorn app:shepherd --host 0.0.0.0" > run.sh
     echo "========================================"
     echo "INSTALL COMPLETE: Use 'sh run.sh' to run"
     echo "========================================"
@@ -34,9 +38,9 @@ echo "Poetry failed to install dependancies. Maybe there is no good python versi
 echo "You can manually do that here:"
 echo "  - Guide: https://realpython.com/installing-python/#how-to-build-python-from-source-code"
 echo "  - Offical python docs: https://docs.python.org/3/using/unix.html"
-echo "Alternatively you can use pyenv"
 echo "-------------------------------------------------------------------------------------"
 echo "SOLUTION: install.sh is able to compile python3.10 from source do you want to try?"
+echo "If you are on a pi this will take some hours"
 echo "-------------------------------------------------------------------------------------"
 echo " [y/n] "
 old_stty_cfg=$(stty -g)
@@ -65,7 +69,7 @@ sudo apt-get install -y make build-essential libssl-dev zlib1g-dev \
        libbz2-dev libreadline-dev libsqlite3-dev wget curl llvm \
        libncurses5-dev libncursesw5-dev xz-utils tk-dev
 
-# Get latest python tarball
+# Get python3.10 tarball
 wget https://www.python.org/ftp/python/3.10.6/Python-3.10.6.tgz
 tar xvf Python-3.10.6.tgz
 cd Python-3.10.6
@@ -90,12 +94,15 @@ echo "Installing python dependancies using poetry"
 
 # Try to install the project dependencies again
 if poetry install; then
+    # Can be used with --debug for hot reload
+    touch run.sh
+    echo "poetry run uvicorn app:shepherd --host 0.0.0.0" > run.sh
     echo "========================================"
     echo "Make sure to add poetry to your path    "
     echo "PATH=$PATH:~/.local/bin"
     echo "INSTALL COMPLETE: Use 'sh run.sh' to run"
     echo "========================================"
     exit
 else
-    echo "'poetry install' failed :("
+    echo "'poetry install' failed. There is likely some error log above."
 fi