fix(server): Improve logging consistency (#8012)

- Make process/service startup/shutdown messages consistent
- Configure `uvicorn` to use our logging config instead of its own
- Replace `print(..)` statements in ws_api.py with log statements
- Improve log statements in ws_api.py

rnd/autogpt_server/autogpt_server/executor/manager.py

@@ -659,7 +659,9 @@ class ExecutionManager(AppService):
             initializer=Executor.on_graph_executor_start,
         )
         sync_manager = multiprocessing.Manager()
-        logger.info(f"ExecutionManager started with max-{self.pool_size} graph workers")
+        logger.info(
+            f"[{self.service_name}] Started with max-{self.pool_size} graph workers"
+        )
         while True:
             graph_exec_data = self.queue.get()
             graph_exec_id = graph_exec_data.graph_exec_id

rnd/autogpt_server/autogpt_server/server/rest_api.py

@@ -200,7 +200,7 @@ class AgentServer(AppService):
 
         app.include_router(router)
 
-        uvicorn.run(app, host="0.0.0.0", port=8000)
+        uvicorn.run(app, host="0.0.0.0", port=8000, log_config=None)
 
     def set_test_dependency_overrides(self, overrides: dict):
         self._test_dependency_overrides = overrides

rnd/autogpt_server/autogpt_server/server/ws_api.py

@@ -13,6 +13,7 @@ from autogpt_server.server.model import ExecutionSubscription, Methods, WsMessag
 from autogpt_server.util.service import AppProcess
 from autogpt_server.util.settings import Settings
 
+logger = logging.getLogger(__name__)
 settings = Settings()
 
 app = FastAPI()
@@ -93,7 +94,7 @@ async def handle_subscribe(
     else:
         ex_sub = ExecutionSubscription.model_validate(message.data)
         await manager.subscribe(ex_sub.graph_id, websocket)
-        print("subscribed")
+        logger.debug(f"New execution subscription for graph {ex_sub.graph_id}")
         await websocket.send_text(
             WsMessage(
                 method=Methods.SUBSCRIBE,
@@ -117,7 +118,7 @@ async def handle_unsubscribe(
     else:
         ex_sub = ExecutionSubscription.model_validate(message.data)
         await manager.unsubscribe(ex_sub.graph_id, websocket)
-        print("unsubscribed")
+        logger.debug(f"Removed execution subscription for graph {ex_sub.graph_id}")
         await websocket.send_text(
             WsMessage(
                 method=Methods.UNSUBSCRIBE,
@@ -151,11 +152,12 @@ async def websocket_router(
                 await handle_unsubscribe(websocket, manager, message)
 
             elif message.method == Methods.ERROR:
-                logging.error("WebSocket Error message received:", message.data)
+                logger.error(f"WebSocket Error message received: {message.data}")
 
             else:
-                logging.info(
-                    f"Message type {message.method} is not processed by the server"
+                logger.warning(
+                    f"Unknown WebSocket message type {message.method} received: "
+                    f"{message.data}"
                 )
                 await websocket.send_text(
                     WsMessage(
@@ -167,7 +169,7 @@ async def websocket_router(
 
     except WebSocketDisconnect:
         manager.disconnect(websocket)
-        logging.info("Client Disconnected")
+        logger.debug("WebSocket client disconnected")
 
 
 class WebsocketServer(AppProcess):

rnd/autogpt_server/autogpt_server/util/process.py

@@ -52,9 +52,10 @@ class AppProcess(ABC):
             if silent:
                 sys.stdout = open(os.devnull, "w")
                 sys.stderr = open(os.devnull, "w")
+            logger.info(f"[{self.__class__.__name__}] Starting...")
             self.run()
-        except (KeyboardInterrupt, SystemExit):
-            logger.info(f"[{self.__class__.__name__}] Terminated; quitting...")
+        except (KeyboardInterrupt, SystemExit) as e:
+            logger.warning(f"[{self.__class__.__name__}] Terminated: {e}; quitting...")
 
     def _self_terminate(self, signum: int, frame):
         self.cleanup()

rnd/autogpt_server/autogpt_server/util/service.py

@@ -44,19 +44,15 @@ def expose(func: C) -> C:
 
 class PyroNameServer(AppProcess):
     def run(self):
-        try:
-            print("Starting NameServer loop")
-            nameserver.start_ns_loop(host=pyro_host, port=9090)
-        except KeyboardInterrupt:
-            print("Shutting down NameServer")
+        nameserver.start_ns_loop(host=pyro_host, port=9090)
 
     @conn_retry
     def _wait_for_ns(self):
         pyro.locate_ns(host="localhost", port=9090)
-        print("NameServer is ready")
 
     def health_check(self):
         self._wait_for_ns()
+        logger.info(f"{__class__.__name__} is ready")
 
 
 class AppService(AppProcess):
@@ -116,7 +112,7 @@ class AppService(AppProcess):
         ns = pyro.locate_ns(host=pyro_host, port=9090)
         uri = daemon.register(self)
         ns.register(self.service_name, uri)
-        logger.info(f"Service [{self.service_name}] Ready. Object URI = {uri}")
+        logger.info(f"[{self.service_name}] Connected to Pyro; URI = {uri}")
         daemon.requestLoop()
 
     def __start_async_loop(self):