add logger file and improve loggers

Author: naderzare

server.py

@@ -4,23 +4,31 @@
 import service_pb2 as pb2
 from typing import Union
 from multiprocessing import Manager, Lock
+from utils.logger_utils import setup_logger
 import logging
 import grpc
 import argparse
 
 
-logging.basicConfig(level=logging.DEBUG)
+console_logging_level = logging.INFO
+file_logging_level = logging.DEBUG
+
+main_logger = setup_logger("pmservice", "logs/pmservice.log", console_level=console_logging_level, file_level=file_logging_level)
+
 
 class GrpcAgent:
-    def __init__(self, agent_type, uniform_number) -> None:
+    def __init__(self, agent_type, uniform_number, logger) -> None:
         self.agent_type: pb2.AgentType = agent_type
         self.uniform_number: int = uniform_number
         self.server_params: Union[pb2.ServerParam, None] = None
         self.player_params: Union[pb2.PlayerParam, None] = None
         self.player_types: dict[int, pb2.PlayerType] = {}
         self.debug_mode: bool = False
+        self.logger: logging.Logger = logger
 
     def GetAction(self, state: pb2.State):
+        self.logger.debug(f"================================= cycle={state.world_model.cycle}.{state.world_model.stoped_cycle} =================================")
+        # self.logger.debug(f"State: {state}")
         if self.agent_type == pb2.AgentType.PlayerT:
             return self.GetPlayerActions(state)
         elif self.agent_type == pb2.AgentType.CoachT:
@@ -50,8 +58,19 @@ def GetPlayerActions(self, state: pb2.State):
                 actions.append(pb2.PlayerAction(helios_basic_move=pb2.HeliosBasicMove()))
         else:
             actions.append(pb2.PlayerAction(helios_set_play=pb2.HeliosSetPlay()))
+        
+        self.logger.debug(f"Actions: {actions}")
         return pb2.PlayerActions(actions=actions)
 
+    def GetBestPlannerAction(self, pairs: pb2.BestPlannerActionRequest):
+        self.logger.debug(f"GetBestPlannerAction cycle:{pairs.state.world_model.cycle} pairs:{len(pairs.pairs)} unum:{pairs.state.register_response.uniform_number}")
+        pairs_list: list[int, pb2.RpcActionState] = [(k, v) for k, v in pairs.pairs.items()]
+        pairs_list.sort(key=lambda x: x[0])
+        best_action = max(pairs_list, key=lambda x: -1000 if x[1].action.parent_index != -1 else x[1].predict_state.ball_position.x)
+        self.logger.debug(f"Best action: {best_action[0]} {best_action[1].action.description} to {best_action[1].action.target_unum} in ({round(best_action[1].action.target_point.x, 2)},{round(best_action[1].action.target_point.y, 2)}) e:{round(best_action[1].evaluation,2)}")
+        res = pb2.BestPlannerActionResponse(index=best_action[0])
+        return res
+    
     def GetCoachActions(self, state: pb2.State):
         actions = []
         actions.append(pb2.CoachAction(do_helios_substitute=pb2.DoHeliosSubstitute()))
@@ -74,6 +93,21 @@ def GetTrainerActions(self, state: pb2.State):
             )
         )
         return pb2.TrainerActions(actions=actions)
+    
+    def SetServerParams(self, server_params: pb2.ServerParam):
+        self.logger.debug(f"Server params received unum {server_params.register_response.uniform_number}")
+        # self.logger.debug(f"Server params: {server_params}")
+        self.server_params = server_params
+        
+    def SetPlayerParams(self, player_params: pb2.PlayerParam):
+        self.logger.debug(f"Player params received unum {player_params.register_response.uniform_number}")
+        # self.logger.debug(f"Player params: {player_params}")
+        self.player_params = player_params
+        
+    def SetPlayerType(self, player_type: pb2.PlayerType):
+        self.logger.debug(f"Player type received unum {player_type.register_response.uniform_number}")
+        # self.logger.debug(f"Player type: {player_type}")
+        self.player_types[player_type.id] = player_type
 
 class GameHandler(pb2_grpc.GameServicer):
     def __init__(self, shared_lock, shared_number_of_connections) -> None:
@@ -82,91 +116,89 @@ def __init__(self, shared_lock, shared_number_of_connections) -> None:
         self.shared_number_of_connections = shared_number_of_connections
 
     def GetPlayerActions(self, state: pb2.State, context):
-        logging.debug(f"GetPlayerActions unum {state.register_response.uniform_number} at {state.world_model.cycle}")
+        main_logger.debug(f"GetPlayerActions unum {state.register_response.uniform_number} at {state.world_model.cycle}")
         res = self.agents[state.register_response.client_id].GetAction(state)
-        logging.debug(f"GetPlayerActions Done unum {res}")
         return res
 
     def GetCoachActions(self, state: pb2.State, context):
-        logging.debug(f"GetCoachActions coach at {state.world_model.cycle}")
+        main_logger.debug(f"GetCoachActions coach at {state.world_model.cycle}")
         res = self.agents[state.register_response.client_id].GetAction(state)
         return res
 
     def GetTrainerActions(self, state: pb2.State, context):
-        logging.debug(f"GetTrainerActions trainer at {state.world_model.cycle}")
+        main_logger.debug(f"GetTrainerActions trainer at {state.world_model.cycle}")
         res = self.agents[state.register_response.client_id].GetAction(state)
         return res
 
     def SendServerParams(self, serverParams: pb2.ServerParam, context):
-        logging.debug(f"Server params received unum {serverParams.register_response.uniform_number}")
-        self.agents[serverParams.register_response.client_id].server_params = serverParams
+        main_logger.debug(f"Server params received unum {serverParams.register_response.uniform_number}")
+        self.agents[serverParams.register_response.client_id].SetServerParams(serverParams)
         res = pb2.Empty()
         return res
 
     def SendPlayerParams(self, playerParams: pb2.PlayerParam, context):
-        logging.debug(f"Player params received unum {playerParams.register_response.uniform_number}")
-        self.agents[playerParams.register_response.client_id].player_params = playerParams
+        main_logger.debug(f"Player params received unum {playerParams.register_response.uniform_number}")
+        self.agents[playerParams.register_response.client_id].SetPlayerParams(playerParams)
         res = pb2.Empty()
         return res
 
     def SendPlayerType(self, playerType: pb2.PlayerType, context):
-        logging.debug(f"Player type received unum {playerType.register_response.uniform_number}")
-        self.agents[playerType.register_response.client_id].player_types[playerType.id] = playerType
+        main_logger.debug(f"Player type received unum {playerType.register_response.uniform_number}")
+        self.agents[playerType.register_response.client_id].SetPlayerType(playerType)
         res = pb2.Empty()
         return res
 
     def SendInitMessage(self, initMessage: pb2.InitMessage, context):
-        logging.debug(f"Init message received unum {initMessage.register_response.uniform_number}")
+        main_logger.debug(f"Init message received unum {initMessage.register_response.uniform_number}")
         self.agents[initMessage.register_response.client_id].debug_mode = initMessage.debug_mode
         res = pb2.Empty()
         return res
 
     def Register(self, register_request: pb2.RegisterRequest, context):
-        logging.debug(f"received register request from team_name: {register_request.team_name} "
-                      f"unum: {register_request.uniform_number} "
-                      f"agent_type: {register_request.agent_type}")
         with self.shared_lock:
+            main_logger.info(f"received register request from team_name: {register_request.team_name} "
+                f"unum: {register_request.uniform_number} "
+                f"agent_type: {register_request.agent_type}")
             self.shared_number_of_connections.value += 1
-            logging.debug(f"Number of connections {self.shared_number_of_connections.value}")
+            main_logger.info(f"Number of connections {self.shared_number_of_connections.value}")
             team_name = register_request.team_name
             uniform_number = register_request.uniform_number
             agent_type = register_request.agent_type
-            self.agents[self.shared_number_of_connections.value] = GrpcAgent(agent_type, uniform_number)
-            res = pb2.RegisterResponse(client_id=self.shared_number_of_connections.value,
+            register_response = pb2.RegisterResponse(client_id=self.shared_number_of_connections.value,
                                     team_name=team_name,
                                     uniform_number=uniform_number,
                                     agent_type=agent_type)
-        return res
+            logger = setup_logger(f"agent{register_response.uniform_number}_{register_response.client_id}")
+            self.agents[self.shared_number_of_connections.value] = GrpcAgent(agent_type, uniform_number, logger)
+        return register_response
 
     def SendByeCommand(self, register_response: pb2.RegisterResponse, context):
-        logging.debug(f"Bye command received unum {register_response.uniform_number}")
+        main_logger.debug(f"Bye command received unum {register_response.uniform_number}")
         # with shared_lock:
         self.agents.pop(register_response.client_id)
 
         res = pb2.Empty()
         return res
 
     def GetBestPlannerAction(self, pairs: pb2.BestPlannerActionRequest, context):
-        logging.debug(f"GetBestPlannerAction cycle:{pairs.state.world_model.cycle} pairs:{len(pairs.pairs)} unum:{pairs.state.register_response.uniform_number}")
-        pairs_list: list[int, pb2.RpcActionState] = [(k, v) for k, v in pairs.pairs.items()]
-        pairs_list.sort(key=lambda x: x[0])
-        best_action = max(pairs_list, key=lambda x: -1000 if x[1].action.parent_index != -1 else x[1].predict_state.ball_position.x)
-        logging.debug(f"Best action: {best_action[0]} {best_action[1].action.description} to {best_action[1].action.target_unum} in ({round(best_action[1].action.target_point.x, 2)},{round(best_action[1].action.target_point.y, 2)}) e:{round(best_action[1].evaluation,2)}")
-        res = pb2.BestPlannerActionResponse(index=best_action[0])
+        main_logger.debug(f"GetBestPlannerAction cycle:{pairs.state.world_model.cycle} pairs:{len(pairs.pairs)} unum:{pairs.state.register_response.uniform_number}")
+        res = self.agents[pairs.state.register_response.client_id].GetBestPlannerAction(pairs)
         return res
+    
 
 def serve(port, shared_lock, shared_number_of_connections):
     server = grpc.server(futures.ThreadPoolExecutor(max_workers=22))
     game_service = GameHandler(shared_lock, shared_number_of_connections)
     pb2_grpc.add_GameServicer_to_server(game_service, server)
     server.add_insecure_port(f'[::]:{port}')
     server.start()
-    logging.info(f"Starting server on port {port}")
+    main_logger.info(f"Starting server on port {port}")
 
     server.wait_for_termination()
 
 
 def main():
+    main_logger.info("Starting server")
     manager = Manager()
     shared_lock = Lock()  # Create a Lock for synchronization
     shared_number_of_connections = manager.Value('i', 0)

start-team.py

@@ -5,10 +5,14 @@
 import logging
 import argparse
 import check_requirements
+from utils.logger_utils import setup_logger
 
 
+# remove logs directory
+os.system("rm -rf logs")
+
 # Set up logging
-logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s')
+start_team_logger = setup_logger('start-team', 'logs/start-team.log', console_level=logging.DEBUG, file_level=logging.DEBUG, console_format_str='%(message)s')
 
 def run_server_script(args):
     # Start the server.py script as a new process group
@@ -31,12 +35,20 @@ def run_start_script(args):
     )
     return process
 
-def stream_output(process, prefix):
+def stream_output_to_console(process, prefix):
     # Stream output from the process and log it with a prefix
     for line in iter(process.stdout.readline, b''):
-        logging.debug(f'{prefix} {line.decode().strip()}')
+        start_team_logger.debug(f'{prefix} {line.decode().strip()}')
     process.stdout.close()
 
+def stream_output_to_file(process, prefix):
+    # Stream output from the process and log it with a prefix
+    logger = setup_logger(prefix, console_level=None, file_level=logging.DEBUG)
+    for line in iter(process.stdout.readline, b''):
+        logger.info(line.decode().strip())
+        pass
+    process.stdout.close()
+    
 def kill_process_group(process):
     try:
         os.killpg(os.getpgid(process.pid), signal.SIGTERM)  # Send SIGTERM to the process group
@@ -52,20 +64,20 @@ def kill_process_group(process):
 
     try:
         # Check Python requirements
-        logging.debug("Checking Python requirements...")
+        start_team_logger.debug("Checking Python requirements...")
         check_requirements.check_requirements()
 
         # Run the server.py script first
         server_process = run_server_script(args)
-        logging.debug(f"Started server.py process with PID: {server_process.pid}")
+        start_team_logger.debug(f"Started server.py process with PID: {server_process.pid}")
 
         # Run the start.sh script after server.py with the given arguments
         start_process = run_start_script(args)
-        logging.debug(f"Started start.sh process with PID: {start_process.pid} with team name {args=}")
+        start_team_logger.debug(f"Started start.sh process with PID: {start_process.pid} with team name {args=}")
 
         # Monitor both processes and log their outputs
-        server_thread = threading.Thread(target=stream_output, args=(server_process, 'server:'))
-        start_thread = threading.Thread(target=stream_output, args=(start_process, 'team:'))
+        server_thread = threading.Thread(target=stream_output_to_console, args=(server_process, 'server:'))
+        start_thread = threading.Thread(target=stream_output_to_file, args=(start_process, 'proxy:'))
 
         server_thread.start()
         start_thread.start()
@@ -75,7 +87,7 @@ def kill_process_group(process):
         start_thread.join()
 
     except KeyboardInterrupt:
-        logging.debug("Interrupted! Killing all processes.")
+        start_team_logger.debug("Interrupted! Killing all processes.")
         kill_process_group(server_process)
         kill_process_group(start_process)
 

start-team.sh

@@ -1,5 +1,12 @@
 #!/bin/bash
 
+# remove logs directory
+rm -rf logs
+# create logs directory
+if [ ! -d "./logs" ]; then
+  mkdir -p "./logs"
+fi
+
 # Ensure the script exits if any command fails
 set -e
 # check scripts/proxy directory does not exist, raise error
@@ -67,8 +74,10 @@ sleep 2
 
 # Start start.sh script in the correct directory with arguments
 echo "Starting start.sh with team name: $team_name and ..."
+log_dir="logs/proxy.log"
+abspath=$(realpath $log_dir)
 cd scripts/proxy
-bash start.sh -t "$team_name" --rpc-port $rpc_port --rpc-type grpc &
+bash start.sh -t "$team_name" --rpc-port $rpc_port --rpc-type grpc >> $abspath 2>&1 &
 start_pid=$!
 
 # Wait for both background processes to finish

utils/logger_utils.py

@@ -0,0 +1,50 @@
+import logging
+import os
+
+
+def setup_logger(name, log_file=None, console_level=logging.INFO, file_level=logging.DEBUG, console_format_str=None, file_format_str=None):
+    """
+    Set up a logger that writes to both a file and the console, with different formats and levels.
+    
+    :param name: Name of the logger.
+    :param log_file: Path to the log file.
+    :param console_level: Logging level for the console output.
+    :param file_level: Logging level for the file output.
+    :return: Configured logger.
+    """
+    have_console_handler = console_level is not None
+    have_file_handler = file_level is not None
+    if log_file is None:
+        log_file = os.path.join('logs', f'{name}.log')
+    # Directory
+    directory = os.path.dirname(log_file)
+    if directory and not os.path.exists(directory):
+        os.makedirs(directory)
+        
+    print(f"have_console_handler={have_console_handler}, have_file_handler={have_file_handler}", log_file, directory)
+    # Create a custom logger
+    logger = logging.getLogger(name)
+    
+    if not logger.hasHandlers():
+        logger.setLevel(logging.DEBUG)  # Set the overall logger level to the lowest level you want to capture
+        # Console handler
+        if have_console_handler:
+            console_handler = logging.StreamHandler()  # For console output
+            console_handler.setLevel(console_level)
+            if not console_format_str:
+                console_format_str = '%(name)s - %(levelname)s - %(message)s'
+            console_format = logging.Formatter(console_format_str)
+            console_handler.setFormatter(console_format)
+            logger.addHandler(console_handler)
+        
+        # File handler
+        if have_file_handler:
+            file_handler = logging.FileHandler(log_file)  # For file output
+            file_handler.setLevel(file_level)
+            if not file_format_str:
+                file_format_str = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
+            file_format = logging.Formatter(file_format_str)
+            file_handler.setFormatter(file_format)
+            logger.addHandler(file_handler)
+    
+    return logger