Fixed orphaned processes and added logging

config.py

@@ -11,3 +11,4 @@ class Config:
     SERVER_RCON_PASSWORD: str | None = data.get("SERVER_RCON_PASSWORD")
     MAINTAINANCE_FILE = data.get("MAINTAINANCE_FILE") or "maintainance.txt"
     LOG_FILE = data.get("LOG_FILE") or "logs.txt"
+    MINECRAFTD_LOGS = data.get("MINECRAFTD_LOGS") or "debug.log"

controllers.py

@@ -2,11 +2,13 @@ import shlex
 from collections import deque
 from pathlib import Path
 from subprocess import PIPE, Popen
+from threading import Lock
 from time import sleep
 from typing import Literal
 
 from classes import ProcessStatus, ServerStatus
 from config import Config
+from logs import logger
 from mcrcon import MCRcon
 from mcstatus import JavaServer
 
@@ -18,10 +20,18 @@ class ProcessController:
         self.last_status: Literal[ProcessStatus.STOPPED, ProcessStatus.CRASHED] = (
             ProcessStatus.STOPPED
         )
+        self._lock = Lock()
 
     def start(self) -> None:
         "Start the process."
+        logger.debug("ProcessController.start()")
+        with self._lock:
             if self.status() == ProcessStatus.RUNNING:
+                if self.process:
+                    logger.debug(
+                        "ProcessController.start() - Process was already running with PID: %s",
+                        self.process.pid,
+                    )
                     return
 
             self.process = Popen(
@@ -29,26 +39,45 @@ class ProcessController:
                 stdout=PIPE,
                 stderr=PIPE,
             )
+            logger.info(
+                "ProcessController.start() - Started process with PID: %s",
+                self.process.pid,
+            )
 
     def status(self) -> ProcessStatus:
         "Check the process' status."
+        logger.debug("ProcessController.status()")
+
         if not self.process:
+            logger.debug("ProcessController.status() => %s", self.last_status)
             return self.last_status
         match self.process.poll():
             case None:
+                logger.debug("ProcessController.status() => ProcessStatus.RUNNING")
                 return ProcessStatus.RUNNING
             case 0:
+                logger.debug("ProcessController.status() => ProcessStatus.STOPPED")
                 self.last_status = ProcessStatus.STOPPED
                 return ProcessStatus.STOPPED
             case _:
+                logger.debug("ProcessController.status() => ProcessStatus.CRASHED")
                 self.last_status = ProcessStatus.CRASHED
                 return ProcessStatus.CRASHED
 
     def kill(self) -> None:
         "Kill the process."
+        logger.debug("ProcessController.kill()")
+        with self._lock:
             if self.process:
-            self.process.terminate()
+                pid = self.process.pid
+                self.process.kill()
+                code = self.process.wait()
                 self.process = None
+                logger.info(
+                    "ProcessController.kill() - Process with PID %s killed with return code: %s",
+                    pid,
+                    code,
+                )
                 self.last_status = ProcessStatus.STOPPED
 
 
@@ -65,9 +94,11 @@ class ServerController:
         )
 
     def status(self) -> ServerStatus:
+        logger.debug("ServerController.status()")
         try:
             status = self.server.status()
         except Exception:
+            logger.debug("ServerController.status() - Server is offline")
             return {"online": False}
 
         players = []
@@ -75,6 +106,7 @@ class ServerController:
             for player in status.players.sample:
                 players.append(player.name)
 
+        logger.debug("ServerController.status() - Server is online")
         return {
             "online": True,
             "icon": status.icon,
@@ -87,12 +119,18 @@ class ServerController:
         }
 
     def command(self, command: str) -> str:
+        logger.debug('ServerController.command(command="%s")', command)
         try:
             self.rcon.connect()
             output = self.rcon.command(command)
             self.rcon.disconnect()
+            logger.info('ServerController.command(command="%s") => %s', command, output)
             return output
         except Exception:
+            logger.exception(
+                'ServerController.command(command="%s") - Command execution failed',
+                command,
+            )
             return ""
 
 
@@ -101,19 +139,28 @@ class MaintainanceController:
         self.mnt_file = Path(Config.MAINTAINANCE_FILE)
 
     def set(self, reason: str):
+        logger.debug('MaintainanceController.set(reason="%s")', reason)
         self.mnt_file.write_text(reason)
 
     def is_set(self) -> bool:
+        logger.debug("MaintainanceController.is_set() => %s", self.mnt_file.is_file())
         return self.mnt_file.is_file()
 
     def get(self) -> str:
         if self.is_set():
+            logger.debug(
+                "MaintainanceController.get() => %s", self.mnt_file.read_text()
+            )
             return self.mnt_file.read_text()
+
+        logger.debug("MaintainanceController.get() => ")
         return ""
 
     def unset(self):
+        logger.debug("MaintainanceController.unset()")
         if self.is_set():
             self.mnt_file.unlink()
+            logger.debug("MaintainanceController.unset() - Maintainance file was unset")
 
 
 class LogsController:
@@ -121,16 +168,21 @@ class LogsController:
         self.log_file = Path(Config.LOG_FILE)
 
     def stream(self):
+        logger.debug("LogsController.stream()")
+        i = 0
         with self.log_file.open() as f:
             f.seek(0, 2)
             while True:
                 line = f.readline()
                 if line:
+                    logger.debug("LogsController.stream() - Yielding line %s", i)
+                    i += 1
                     yield line
                 else:
                     sleep(0.1)
 
     def tail(self, back: int = 10):
+        logger.debug("LogsController.tail(back=%s)", back)
         with self.log_file.open() as f:
             for line in deque(f, maxlen=back):
                 yield line

logs.py

@@ -0,0 +1,15 @@
+from logging import DEBUG, INFO, FileHandler, Formatter, StreamHandler, getLogger
+
+from config import Config
+
+logger = getLogger(__name__)
+logger.setLevel(DEBUG)
+console = StreamHandler()
+console.setLevel(INFO)
+file = FileHandler(Config.MINECRAFTD_LOGS)
+file.setLevel(DEBUG)
+formatter = Formatter("%(asctime)s - %(levelname)s - %(message)s")
+console.setFormatter(formatter)
+file.setFormatter(formatter)
+logger.addHandler(console)
+logger.addHandler(file)

main.py

@@ -1,11 +1,11 @@
-from asyncio import create_task
 from typing import Annotated, Optional
 
 import uvicorn
 from classes import ProcessStatus
 from controllers import Controllers
-from fastapi import FastAPI, Header
+from fastapi import BackgroundTasks, FastAPI, Header
 from fastapi.responses import StreamingResponse
+from logs import logger
 from models import Models
 from responses import Responses
 from util import check_password, stop_server
@@ -14,14 +14,17 @@ app = FastAPI()
 
 
 @app.get("/start")
-async def start() -> Responses.StartResponse:
+async def start(tasks: BackgroundTasks) -> Responses.StartResponse:
     """Starts the Server's process if it is not already running.
     Returns:
         status: "started" or "running".
         message: The Server's response.
     """
 
+    logger.debug("/start")
+
     if Controllers.process.status() == ProcessStatus.RUNNING:
+        logger.debug("/start - The Server was already running")
         return {
             "status": "running",
             "message": "The Server was already running.",
@@ -29,11 +32,13 @@ async def start() -> Responses.StartResponse:
 
     if Controllers.maintainance.is_set():
         Controllers.maintainance.unset()
+        logger.debug("/start - Unset maintainance")
 
-    Controllers.process.start()
+    tasks.add_task(Controllers.process.start)
+    logger.info("/start - Starting server")
     return {
-        "status": "started",
+        "status": "starting",
-        "message": "The Server was started.",
+        "message": "The Server is starting.",
     }
 
 
@@ -52,22 +57,30 @@ async def status() -> Responses.StatusResponse:
             list: the list of online players' usernames as strings.
     """
 
+    logger.debug("/status")
+
     process_status = Controllers.process.status()
     if process_status != ProcessStatus.RUNNING:
         # Crashed
         if process_status == ProcessStatus.CRASHED:
+            logger.debug("/status - The Server has crashed")
             return {
                 "status": "crashed",
                 "message": "The Server has crashed.",
             }
         # Maintainance
         if Controllers.maintainance.is_set():
+            reason = Controllers.maintainance.get()
+            logger.debug(
+                '/status - The Server is offline due to maintainance ("%s")', reason
+            )
             return {
                 "status": "maintainance",
                 "message": "The Server is offline due to maintainance.",
-                "reason": Controllers.maintainance.get(),
+                "reason": reason,
             }
         # Offline
+        logger.debug("/status - The Server is offline")
         return {
             "status": "offline",
             "message": "The Server is offline.",
@@ -77,12 +90,14 @@ async def status() -> Responses.StatusResponse:
 
     # Starting
     if not server_status["online"]:
+        logger.debug("/status - The Server is starting")
         return {
             "status": "starting",
             "message": "The Server is starting.",
         }
 
     # Online
+    logger.debug("/status - The Server is online")
     return {
         "status": "online",
         "message": "The Server is online.",
@@ -101,7 +116,9 @@ async def status() -> Responses.StatusResponse:
 
 @app.get("/stop")
 async def stop(
-    data: Models.StopModel, authorization: Annotated[str, Header()]
+    data: Models.StopModel,
+    authorization: Annotated[str, Header()],
+    tasks: BackgroundTasks,
 ) -> Responses.StopResponse:
     """Stops the Server.
     It waits for `countdown` seconds, then runs `/stop` on the Server, and kills it after `timeout` seconds if it's still alive.
@@ -117,8 +134,12 @@ async def stop(
         message: The Server's response.
     """
 
+    logger.debug("/stop")
+
     check_password(authorization)
-    create_task(stop_server("STOPPING", data.countdown, data.reason, data.timeout))
+    tasks.add_task(stop_server, "STOPPING", data.countdown, data.reason, data.timeout)
+
+    logger.info("/stop - The Server is stopping")
     return {
         "status": "stopping",
         "message": "The Server is stopping.",
@@ -127,7 +148,9 @@ async def stop(
 
 @app.get("/restart")
 async def restart(
-    data: Models.RestartModel, authorization: Annotated[str, Header()]
+    data: Models.RestartModel,
+    authorization: Annotated[str, Header()],
+    tasks: BackgroundTasks,
 ) -> Responses.RestartResponse:
     """Restarts the Server.
     It waits for `countdown` seconds, then runs `/stop` on the Server, and kills it after `timeout` seconds if it's still alive.
@@ -145,15 +168,20 @@ async def restart(
     """
 
     check_password(authorization)
-    create_task(
+
-        stop_server(
+    logger.debug("/restart")
+
+    tasks.add_task(
+        stop_server,
         "RESTARTING",
         data.countdown,
         data.reason,
         data.timeout,
         Controllers.process.start,
     )
-    )
+
+    logger.info("/restart - The Server is restarting")
+
     return {
         "status": "restarting",
         "message": "The Server is restarting.",
@@ -162,7 +190,9 @@ async def restart(
 
 @app.get("/maintainance")
 async def maintainance(
-    data: Models.MaintainanceModel, authorization: Annotated[str, Header()]
+    data: Models.MaintainanceModel,
+    authorization: Annotated[str, Header()],
+    tasks: BackgroundTasks,
 ) -> Responses.MaintainanceResponse:
     """Stops the Server and sets it to maintainance status.
     It waits for `countdown` seconds, then runs `/stop` on the Server, and kills it after `timeout` seconds if it's still alive.
@@ -179,15 +209,21 @@ async def maintainance(
     """
 
     check_password(authorization)
-    create_task(
+
-        stop_server(
+    logger.debug("/maintainance")
+
+    tasks.add_task(
+        stop_server,
         "STOPPING FOR MAINTAINANCE",
         data.countdown,
         data.reason,
         data.timeout,
-            Controllers.maintainance.set(data.reason),
+        Controllers.maintainance.set,
-        )
+        data.reason,
     )
+
+    logger.info("/maintainance - The Server is stopping for maintainance")
+
     return {
         "status": "stopping",
         "message": "The Server is stopping for maintainance.",
@@ -210,11 +246,14 @@ async def command(
         output: The command's output.
     """
 
+    logger.debug('/command {command: "%s"}', data.command)
     check_password(authorization)
+
+    output = Controllers.server.command(data.command)
     return {
         "status": "executed",
         "message": "The command was executed.",
-        "output": Controllers.server.command(data.command),
+        "output": output,
     }
 
 
@@ -227,6 +266,7 @@ async def logs_stream(authorization: Annotated[str, Header()]) -> StreamingRespo
     Returns: text/event-stream
     """
 
+    logger.debug("/logs/stream")
     check_password(authorization)
     return StreamingResponse(Controllers.logs.stream(), media_type="text/event-stream")
 
@@ -244,6 +284,7 @@ async def logs_tail(
     Returns: text/event-stream
     """
 
+    logger.debug("/logs/tail")
     check_password(authorization)
     return StreamingResponse(Controllers.logs.tail(data.back if data else 10))
 

responses.py

@@ -4,7 +4,7 @@ from typing_extensions import TypedDict
 
 
 class StartResponse(TypedDict):
-    status: Literal["running", "started"]
+    status: Literal["running", "starting"]
     message: str
 
 

util.py

@@ -1,14 +1,21 @@
-from asyncio import sleep
+from time import sleep
 from typing import Callable
 
 from classes import ProcessStatus
 from config import Config
 from controllers import Controllers
 from fastapi import HTTPException
+from logs import logger
 
 
-async def stop_server(
+def stop_server(
-    action: str, countdown: int, reason: str, timeout: int, then: Callable | None = None
+    action: str,
+    countdown: int,
+    reason: str,
+    timeout: int,
+    then: Callable | None = None,
+    *args,
+    **kwargs,
 ):
     """Warns the players, stops the Server, and kills its process if its taking too long.
 
@@ -19,27 +26,42 @@ async def stop_server(
         timeout (int): Seconds to wait before killing the process.
         then (Callable | None) (default: None): Function to be called after the Server is stopped.
     """
+    logger.debug(
+        'stop_server(action="%s", countdown=%s, reason="%s", timeout=%s, then=%s, args=%s, kwargs=%s',
+        action,
+        countdown,
+        reason,
+        timeout,
+        then,
+        args,
+        kwargs,
+    )
     if countdown:
+        logger.debug("stop_server(...) - Starting countdown")
         Controllers.server.command(f"say SERVER IS {action} IN {countdown} SECONDS!!!")
         Controllers.server.command(f"say REASON: '{reason}'")
         while countdown > 0 and Controllers.server.status().get("players", {}).get(
             "online", 0
         ):
-            await sleep(1)
+            sleep(1)
             countdown -= 1
 
+    logger.info("stop_server(...) - Stopping server")
     Controllers.server.command("stop")
     while timeout > 0 and Controllers.process.status() == ProcessStatus.RUNNING:
-        await sleep(1)
+        sleep(1)
         timeout -= 1
 
     if Controllers.process.status() == ProcessStatus.RUNNING:
+        logger.warning("stop_server(...) - Killing server")
         Controllers.process.kill()
 
     if then:
-        then()
+        logger.debug("stop_server(...) - Running callback")
+        then(*args, **kwargs)
 
 
 def check_password(password: str):
     if password != Config.MINECRAFTD_PASSWORD:
+        logger.debug('check_password("%s") - Password is invalid', password)
         raise HTTPException(401, "Password is invalid")