From 84910811eeb468cae76e62a490ddb7856aaf4898 Mon Sep 17 00:00:00 2001 From: Edwin Shepherd <13338287+shardros@users.noreply.github.com> Date: Sun, 28 Aug 2022 20:41:48 +0100 Subject: [PATCH] Sheep compatiability (#21) This PR will be merged when there is all of the parts which sheep needs to run working. --- .gitignore | 3 +- app/logging.py | 19 +++++++---- app/main.py | 6 ++-- app/run.py | 82 ++++++++++++++++++++++++--------------------- app/upload.py | 4 +++ install.sh | 19 +++++++---- poetry.lock | 47 +++++++++++++++++++++++++- pyproject.toml | 4 ++- run.sh | 1 - test/convenience.py | 28 +++++++++------- test/test_runner.py | 3 +- 11 files changed, 145 insertions(+), 71 deletions(-) delete mode 100644 run.sh diff --git a/.gitignore b/.gitignore index 7d576aa..7e616ba 100644 --- a/.gitignore +++ b/.gitignore @@ -149,4 +149,5 @@ usercode/editable/* !usercode/editable/main.py !usercode/editable/minimal_example.py !usercode/editable/snippests.py -logs.txt \ No newline at end of file +logs.txt +run.sh diff --git a/app/logging.py b/app/logging.py index 6818f83..8ff9e29 100644 --- a/app/logging.py +++ b/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,6 +90,10 @@ 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: @@ -97,18 +101,19 @@ def configure_logger(name: str, new_fomater, level): 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") diff --git a/app/main.py b/app/main.py index 7ef27a8..6d27fe3 100644 --- a/app/main.py +++ b/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,7 +33,7 @@ @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() @@ -40,6 +41,7 @@ def startup_event(): @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) diff --git a/app/run.py b/app/run.py index f68b210..b4dd51d 100644 --- a/app/run.py +++ b/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() diff --git a/app/upload.py b/app/upload.py index 51a192e..7ac840c 100644 --- a/app/upload.py +++ b/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: diff --git a/install.sh b/install.sh index 0ea3d1f..84f5f7c 100644 --- a/install.sh +++ b/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,6 +94,9 @@ 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" @@ -97,5 +104,5 @@ if poetry install; then echo "========================================" exit else - echo "'poetry install' failed :(" + echo "'poetry install' failed. There is likely some error log above." fi diff --git a/poetry.lock b/poetry.lock index 2259b9c..3718e41 100644 --- a/poetry.lock +++ b/poetry.lock @@ -257,6 +257,17 @@ python-versions = "*" [package.dependencies] colorama = "*" +[[package]] +name = "psutil" +version = "5.9.1" +description = "Cross-platform lib for process and system monitoring in Python." +category = "main" +optional = false +python-versions = ">=2.7, !=3.0.*, !=3.1.*, !=3.2.*, !=3.3.*" + +[package.extras] +test = ["ipaddress", "mock", "enum34", "pywin32", "wmi"] + [[package]] name = "py" version = "1.11.0" @@ -500,7 +511,7 @@ python-versions = "!=3.0.*,!=3.1.*,!=3.2.*,!=3.3.*,!=3.4.*,>=2.7" [metadata] lock-version = "1.1" python-versions = "^3.10" -content-hash = "f0bbd8a448288d54536f16ac57154a5b8ea752eca245e0981aa6ee1f57ec488d" +content-hash = "a34d95c9eadaba54c845bf30bef3d1fd40881ae646c21b4b166c0fba6b37819f" [metadata.files] aiofiles = [ @@ -634,6 +645,40 @@ pretty-errors = [ {file = "pretty_errors-1.2.25-py3-none-any.whl", hash = "sha256:8ce68ccd99e0f2a099265c8c1f1c23b7c60a15d69bb08816cb336e237d5dc983"}, {file = "pretty_errors-1.2.25.tar.gz", hash = "sha256:a16ba5c752c87c263bf92f8b4b58624e3b1e29271a9391f564f12b86e93c6755"}, ] +psutil = [ + {file = "psutil-5.9.1-cp27-cp27m-manylinux2010_i686.whl", hash = "sha256:799759d809c31aab5fe4579e50addf84565e71c1dc9f1c31258f159ff70d3f87"}, + {file = "psutil-5.9.1-cp27-cp27m-manylinux2010_x86_64.whl", hash = "sha256:9272167b5f5fbfe16945be3db475b3ce8d792386907e673a209da686176552af"}, + {file = "psutil-5.9.1-cp27-cp27m-win32.whl", hash = "sha256:0904727e0b0a038830b019551cf3204dd48ef5c6868adc776e06e93d615fc5fc"}, + {file = "psutil-5.9.1-cp27-cp27m-win_amd64.whl", hash = "sha256:e7e10454cb1ab62cc6ce776e1c135a64045a11ec4c6d254d3f7689c16eb3efd2"}, + {file = "psutil-5.9.1-cp27-cp27mu-manylinux2010_i686.whl", hash = "sha256:56960b9e8edcca1456f8c86a196f0c3d8e3e361320071c93378d41445ffd28b0"}, + {file = "psutil-5.9.1-cp27-cp27mu-manylinux2010_x86_64.whl", hash = "sha256:44d1826150d49ffd62035785a9e2c56afcea66e55b43b8b630d7706276e87f22"}, + {file = "psutil-5.9.1-cp310-cp310-macosx_10_9_x86_64.whl", hash = "sha256:c7be9d7f5b0d206f0bbc3794b8e16fb7dbc53ec9e40bbe8787c6f2d38efcf6c9"}, + {file = "psutil-5.9.1-cp310-cp310-manylinux_2_12_i686.manylinux2010_i686.manylinux_2_17_i686.manylinux2014_i686.whl", hash = "sha256:abd9246e4cdd5b554a2ddd97c157e292ac11ef3e7af25ac56b08b455c829dca8"}, + {file = "psutil-5.9.1-cp310-cp310-manylinux_2_12_x86_64.manylinux2010_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:29a442e25fab1f4d05e2655bb1b8ab6887981838d22effa2396d584b740194de"}, + {file = "psutil-5.9.1-cp310-cp310-win32.whl", hash = "sha256:20b27771b077dcaa0de1de3ad52d22538fe101f9946d6dc7869e6f694f079329"}, + {file = "psutil-5.9.1-cp310-cp310-win_amd64.whl", hash = "sha256:58678bbadae12e0db55186dc58f2888839228ac9f41cc7848853539b70490021"}, + {file = "psutil-5.9.1-cp36-cp36m-macosx_10_9_x86_64.whl", hash = "sha256:3a76ad658641172d9c6e593de6fe248ddde825b5866464c3b2ee26c35da9d237"}, + {file = "psutil-5.9.1-cp36-cp36m-manylinux_2_12_i686.manylinux2010_i686.manylinux_2_17_i686.manylinux2014_i686.whl", hash = "sha256:a6a11e48cb93a5fa606306493f439b4aa7c56cb03fc9ace7f6bfa21aaf07c453"}, + {file = "psutil-5.9.1-cp36-cp36m-manylinux_2_12_x86_64.manylinux2010_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:068935df39055bf27a29824b95c801c7a5130f118b806eee663cad28dca97685"}, + {file = "psutil-5.9.1-cp36-cp36m-win32.whl", hash = "sha256:0f15a19a05f39a09327345bc279c1ba4a8cfb0172cc0d3c7f7d16c813b2e7d36"}, + {file = "psutil-5.9.1-cp36-cp36m-win_amd64.whl", hash = "sha256:db417f0865f90bdc07fa30e1aadc69b6f4cad7f86324b02aa842034efe8d8c4d"}, + {file = "psutil-5.9.1-cp37-cp37m-macosx_10_9_x86_64.whl", hash = "sha256:91c7ff2a40c373d0cc9121d54bc5f31c4fa09c346528e6a08d1845bce5771ffc"}, + {file = "psutil-5.9.1-cp37-cp37m-manylinux_2_12_i686.manylinux2010_i686.manylinux_2_17_i686.manylinux2014_i686.whl", hash = "sha256:fea896b54f3a4ae6f790ac1d017101252c93f6fe075d0e7571543510f11d2676"}, + {file = "psutil-5.9.1-cp37-cp37m-manylinux_2_12_x86_64.manylinux2010_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:3054e923204b8e9c23a55b23b6df73a8089ae1d075cb0bf711d3e9da1724ded4"}, + {file = "psutil-5.9.1-cp37-cp37m-win32.whl", hash = "sha256:d2d006286fbcb60f0b391741f520862e9b69f4019b4d738a2a45728c7e952f1b"}, + {file = "psutil-5.9.1-cp37-cp37m-win_amd64.whl", hash = "sha256:b14ee12da9338f5e5b3a3ef7ca58b3cba30f5b66f7662159762932e6d0b8f680"}, + {file = "psutil-5.9.1-cp38-cp38-macosx_10_9_x86_64.whl", hash = "sha256:19f36c16012ba9cfc742604df189f2f28d2720e23ff7d1e81602dbe066be9fd1"}, + {file = "psutil-5.9.1-cp38-cp38-manylinux_2_12_i686.manylinux2010_i686.manylinux_2_17_i686.manylinux2014_i686.whl", hash = "sha256:944c4b4b82dc4a1b805329c980f270f170fdc9945464223f2ec8e57563139cf4"}, + {file = "psutil-5.9.1-cp38-cp38-manylinux_2_12_x86_64.manylinux2010_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:4b6750a73a9c4a4e689490ccb862d53c7b976a2a35c4e1846d049dcc3f17d83b"}, + {file = "psutil-5.9.1-cp38-cp38-win32.whl", hash = "sha256:a8746bfe4e8f659528c5c7e9af5090c5a7d252f32b2e859c584ef7d8efb1e689"}, + {file = "psutil-5.9.1-cp38-cp38-win_amd64.whl", hash = "sha256:79c9108d9aa7fa6fba6e668b61b82facc067a6b81517cab34d07a84aa89f3df0"}, + {file = "psutil-5.9.1-cp39-cp39-macosx_10_9_x86_64.whl", hash = "sha256:28976df6c64ddd6320d281128817f32c29b539a52bdae5e192537bc338a9ec81"}, + {file = "psutil-5.9.1-cp39-cp39-manylinux_2_12_i686.manylinux2010_i686.manylinux_2_17_i686.manylinux2014_i686.whl", hash = "sha256:b88f75005586131276634027f4219d06e0561292be8bd6bc7f2f00bdabd63c4e"}, + {file = "psutil-5.9.1-cp39-cp39-manylinux_2_12_x86_64.manylinux2010_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:645bd4f7bb5b8633803e0b6746ff1628724668681a434482546887d22c7a9537"}, + {file = "psutil-5.9.1-cp39-cp39-win32.whl", hash = "sha256:32c52611756096ae91f5d1499fe6c53b86f4a9ada147ee42db4991ba1520e574"}, + {file = "psutil-5.9.1-cp39-cp39-win_amd64.whl", hash = "sha256:f65f9a46d984b8cd9b3750c2bdb419b2996895b005aefa6cbaba9a143b1ce2c5"}, + {file = "psutil-5.9.1.tar.gz", hash = "sha256:57f1819b5d9e95cdfb0c881a8a5b7d542ed0b7c522d575706a80bedc848c8954"}, +] py = [ {file = "py-1.11.0-py2.py3-none-any.whl", hash = "sha256:607c53218732647dff4acdfcd50cb62615cedf612e72d1724fb1a0cc6405b378"}, {file = "py-1.11.0.tar.gz", hash = "sha256:51c75c4126074b472f746a24399ad32f6053d1b34b68d2fa41e558e6f4a98719"}, diff --git a/pyproject.toml b/pyproject.toml index 379f796..17fbb0e 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -18,6 +18,7 @@ requests = "^2.28.0" pytest-timeout = "^2.1.0" python-multipart = "^0.0.5" loguru = "^0.6.0" +psutil = "^5.9.1" [tool.poetry.dev-dependencies] autopep8 = "^1.6.0" @@ -25,8 +26,9 @@ pylint = "^2.6.0" pytest = "^7.1.2" [tool.pytest.ini_options] -testpaths = ["./test/"] +testpaths = ["test/"] filterwarnings = ["ignore: There is no current event loop"] +addopts = "-vx --log-level 10" [tool.mypy] warn_unused_configs = true diff --git a/run.sh b/run.sh deleted file mode 100644 index fdb243a..0000000 --- a/run.sh +++ /dev/null @@ -1 +0,0 @@ -poetry run uvicorn app:shepherd --host 0.0.0.0 diff --git a/test/convenience.py b/test/convenience.py index 6961b99..5172868 100644 --- a/test/convenience.py +++ b/test/convenience.py @@ -1,27 +1,29 @@ """A set of functions to make writing the tests a bit easier""" import time import pytest -import os +import psutil from fastapi.testclient import TestClient from app import shepherd from app.config import config -import app.run @pytest.fixture def client(): - try: - with TestClient(shepherd) as test_client: - yield test_client - finally: - # Don't want to leave the usercode running - user_sp = app.run.runner.user_sp - if user_sp.poll() is None: - user_sp.kill() - user_sp.communicate() - if os.path.exists(config.usr_fifo_path) is True: - os.remove(config.usr_fifo_path) + """A fixture for generating a requests like test client + Makes sure the usercode is dead + Set up and tear down can be placed before and after the with + """ + with TestClient(shepherd) as test_client: + yield test_client + + usercode_name = str(config.round_entry_path) + for p in psutil.process_iter(): + if usercode_name in p.name() or usercode_name in ' '.join(p.cmdline()): + print("usercode still running killing it") + p.terminate() + p.wait() + def wait_until(expr, interval=0.1, timeout=5): start = time.time() diff --git a/test/test_runner.py b/test/test_runner.py index f9c135d..e2e5240 100644 --- a/test/test_runner.py +++ b/test/test_runner.py @@ -18,7 +18,7 @@ def test_inital_state(client): def test_start(client): """Code can be started""" client.post("/run/start") - # wait_until(lambda: client.get("/run/state").json() == "Running") + wait_until(lambda: client.get("/run/state").json() == "Running") response = client.get("/run/state") assert response.status_code == 200 @@ -46,4 +46,5 @@ def test_kill_user_code(client): time.sleep(1) log2 = client.get("/run/logs").json() logging.info("Got logs 2") + assert (log1 == log2)