Improve logger and debug

server.py

@@ -15,9 +15,15 @@
 import logging
 from pyrusgeom.vector_2d import Vector2D
 import argparse
+from utils.logger_utils import setup_logger
+import datetime
 
 
-logging.basicConfig(level=logging.DEBUG)
+console_logging_level = logging.INFO
+file_logging_level = logging.DEBUG
+
+main_logger = None
+log_dir = None
 
 
 class GameHandler:
@@ -28,9 +34,11 @@ def __init__(self, shared_lock, shared_number_of_connections):
         self.debug_mode: bool = False
         self.shared_lock = shared_lock
         self.shared_number_of_connections = shared_number_of_connections
+        self.logger: logging.Logger = setup_logger("Agent", log_dir, console_level=console_logging_level, file_level=file_logging_level)
 
     def GetPlayerActions(self, state: State):
-        logging.debug(f"GetPlayerActions unum {state.register_response.uniform_number} at {state.world_model.cycle}")
+        self.logger.debug(f"================================= cycle={state.world_model.cycle}.{state.world_model.stoped_cycle} =================================")
+        self.logger.debug(f"GetPlayerActions unum {state.register_response.uniform_number} at {state.world_model.cycle}")
         actions = []
         if state.world_model.game_mode_type == GameModeType.PlayOn:
             if state.world_model.myself.is_goalie:
@@ -53,19 +61,24 @@ def GetPlayerActions(self, state: State):
             actions.append(PlayerAction(helios_set_play=HeliosSetPlay()))
 
         res = PlayerActions(actions=actions)
+        self.logger.debug(f"Actions: {res}")
         return res
 
     def GetCoachActions(self, state: State):
-        logging.debug(f"GetCoachActions coach at {state.world_model.cycle}")
+        self.logger.debug(f"================================= cycle={state.world_model.cycle}.{state.world_model.stoped_cycle} =================================")
+        self.logger.debug(f"GetCoachActions coach at {state.world_model.cycle}")
         actions = []
         actions.append(CoachAction(do_helios_substitute=DoHeliosSubstitute()))
-        return CoachActions(actions=actions)
+        res = CoachActions(actions=actions)
+        self.logger.debug(f"Actions: {res}")
+        return res
 
     def GetTrainerActions(self, state: State):
-        logging.debug(f"GetTrainerActions trainer at {state.world_model.cycle}")
+        self.logger.debug(f"================================= cycle={state.world_model.cycle}.{state.world_model.stoped_cycle} =================================")
+        self.logger.debug(f"GetTrainerActions trainer at {state.world_model.cycle}")
         actions = []
         if state.world_model.cycle % 100 == 99:
-            logging.debug(f"Trainer at cycle {state.world_model.cycle}")
+            self.logger.debug(f"Trainer at cycle {state.world_model.cycle}")
             if len(state.world_model.teammates) == 0:
                 return TrainerActions()
             player = state.world_model.teammates[0]
@@ -95,60 +108,65 @@ def GetTrainerActions(self, state: State):
                 )),
                 TrainerAction(do_change_mode=DoChangeMode(game_mode_type=GameModeType.PlayOn))
             ]
-        return TrainerActions(actions=actions)
+        res = TrainerActions(actions=actions)
+        self.logger.debug(f"Actions: {res}")
+        return res
 
     def SendServerParams(self, serverParams: ServerParam):
-        logging.debug(f"Server params received unum {serverParams.register_response.uniform_number}")
+        self.logger.debug(f"Server params received unum {serverParams.register_response.uniform_number}")
         self.server_params = serverParams
         res = Empty()
         return res
 
     def SendPlayerParams(self, playerParams: PlayerParam):
-        logging.debug(f"Player params received unum {playerParams.register_response.uniform_number}")
+        self.logger.debug(f"Player params received unum {playerParams.register_response.uniform_number}")
         self.player_params = playerParams
         res = Empty()
         return res
 
     def SendPlayerType(self, playerType: PlayerType):
-        logging.debug(f"Player type received unum {playerType.register_response.uniform_number}")
+        self.logger.debug(f"Player type received unum {playerType.register_response.uniform_number}")
         self.player_types[playerType.id] = playerType
         res = Empty()
         return res
 
     def SendInitMessage(self, initMessage: InitMessage):
-        logging.debug(f"Init message received unum {initMessage.register_response.uniform_number}")
+        self.logger.debug(f"Init message received unum {initMessage.register_response.uniform_number}")
         self.debug_mode = initMessage.debug_mode
         res = Empty()
         return res
 
     def Register(self, register_request: RegisterRequest):
-        logging.debug(f"received register request from team_name: {register_request.team_name} "
+        self.logger.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:
             self.shared_number_of_connections.value += 1
-            logging.debug(f"Number of connections {self.shared_number_of_connections.value}")
+            self.logger.debug(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.logger: logging.Logger = setup_logger(f"Agent{register_request.uniform_number}-{self.shared_number_of_connections.value}", 
+                                                       log_dir, 
+                                                       console_level=console_logging_level, file_level=file_logging_level)
             res = RegisterResponse(client_id=self.shared_number_of_connections.value,
                                    team_name=team_name,
                                    uniform_number=uniform_number,
                                    agent_type=agent_type)
             return res
 
     def SendByeCommand(self, register_response: RegisterResponse):
-        logging.debug(f"Bye command received unum {register_response.uniform_number}")
+        self.logger.debug(f"Bye command received unum {register_response.uniform_number}")
         with self.shared_lock:
             pass
         res = Empty()
         return res
     def GetBestPlannerAction(self, pairs: BestPlannerActionRequest):
-        logging.debug(f"GetBestPlannerAction cycle:{pairs.state.world_model.cycle} pairs:{len(pairs.pairs)} unum:{pairs.register_response.uniform_number}")
+        self.logger.debug(f"GetBestPlannerAction cycle:{pairs.state.world_model.cycle} pairs:{len(pairs.pairs)} unum:{pairs.register_response.uniform_number}")
         pairs_list: list[int, 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)}")
+        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 = BestPlannerActionResponse(index=best_action[0])
         return res
 
@@ -162,7 +180,7 @@ def serve(port, shared_lock, shared_number_of_connections):
     server = PFProcessServer(processor, transport, tfactory, pfactory)
     # server = TThreadedServer(processor, transport, tfactory, pfactory)
 
-    logging.info(f"Starting server on port {port}")
+    main_logger.info(f"Starting server on port {port}")
     try:
         server.serve()
     except KeyboardInterrupt:
@@ -171,12 +189,18 @@ def serve(port, shared_lock, shared_number_of_connections):
 
 
 def main():
+    global main_logger, log_dir
     manager = Manager()
     shared_lock = Lock()  # Create a Lock for synchronization
     shared_number_of_connections = manager.Value('i', 0)
     parser = argparse.ArgumentParser(description='Run play maker server')
     parser.add_argument('-p', '--rpc-port', required=False, help='The port of the server', default=50051)
+    parser.add_argument('-l', '--log-dir', required=False, help='The directory of the log file', 
+                    default=f'logs/{datetime.datetime.now().strftime("%Y-%m-%d_%H-%M-%S")}')
     args = parser.parse_args()
+    log_dir = args.log_dir
+    main_logger = setup_logger("pmservice", log_dir, console_level=console_logging_level, file_level=file_logging_level)
+
     serve(args.rpc_port, shared_lock, shared_number_of_connections)
 
 

start-team.py

@@ -5,15 +5,18 @@
 import logging
 import argparse
 import check_requirements
-
+from utils.logger_utils import setup_logger
+import datetime
 
 # Set up logging
-logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s')
+log_dir = os.path.join(os.getcwd(), 'logs', datetime.datetime.now().strftime('%Y-%m-%d_%H-%M-%S'))
+start_team_logger = setup_logger('start-team', log_dir, 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
     process = subprocess.Popen(
-        ['python3', 'server.py', '--rpc-port', args.rpc_port],
+        ['python3', 'server.py', '--rpc-port', args.rpc_port, '--log-dir', log_dir],
         preexec_fn=os.setsid,  # Create a new session and set the process group ID
         stdout=subprocess.PIPE,
         stderr=subprocess.STDOUT  # Capture stderr and redirect it to stdout
@@ -23,18 +26,26 @@ def run_server_script(args):
 def run_start_script(args):
     # Start the start.sh script in its own directory as a new process group
     process = subprocess.Popen(
-        ['bash', 'start.sh', '-t', args.team_name, '--rpc-port', args.rpc_port],
+        ['bash', 'start.sh' if not args.debug else 'start-debug.sh', '-t', args.team_name, '--rpc-port', args.rpc_port, '--rpc-type', 'thrift'],
         cwd='scripts/proxy',  # Corrected directory to where start.sh is located
         preexec_fn=os.setsid,  # Create a new session and set the process group ID
         stdout=subprocess.PIPE,
         stderr=subprocess.STDOUT  # Capture stderr and redirect it to stdout
     )
     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, log_dir, 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):
@@ -48,24 +59,26 @@ def kill_process_group(process):
     parser = argparse.ArgumentParser(description='Run server and team scripts.')
     parser.add_argument('-t', '--team_name', required=False, help='The name of the team', default='CLS')
     parser.add_argument('--rpc-port', required=False, help='The port of the server', default='50051')
+    parser.add_argument('-d', '--debug', required=False, help='Enable debug mode', default=False, action='store_true')
+
     args = parser.parse_args()
 
     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 +88,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,13 @@
 #!/bin/bash
 
+# create a log directory with the current date and time
+log_dir="logs/$(date +'%Y-%m-%d_%H-%M-%S')"
+if [ ! -d $log_dir ]; then
+  mkdir -p $log_dir
+fi
+
+abs_log_dir_path=$(realpath $log_dir)
+
 # Ensure the script exits if any command fails
 set -e
 # check scripts/proxy directory does not exist, raise error
@@ -10,6 +18,7 @@ fi
 
 team_name="CLS"
 rpc_port=50051
+debug=false
 
 # help function
 usage() {
@@ -31,6 +40,9 @@ do
       rpc_port=$2
       shift
       ;;
+    -d|--debug)
+      debug=true
+      ;;
     *)
       echo 1>&2
       echo "invalid option \"${1}\"." 1>&2
@@ -49,7 +61,7 @@ python3 check_requirements.py
 
 # Start server.py in the background
 echo "Starting server.py..."
-python3 server.py --rpc-port $rpc_port &
+python3 server.py --rpc-port $rpc_port --log-dir $abs_log_dir_path &
 server_pid=$!
 
 # Function to kill server and team processes on exit
@@ -67,10 +79,17 @@ sleep 2
 
 # Start start.sh script in the correct directory with arguments
 echo "Starting start.sh with team name: $team_name and ..."
+
+start_log_path="$abs_log_dir_path/proxy.log"
+
 cd scripts/proxy
-bash start.sh -t "$team_name" --rpc-port $rpc_port &
-start_pid=$!
+if [ "$debug" = true ]; then
+  bash start-debug.sh -t "$team_name" --rpc-port $rpc_port --rpc-type thrift >> $start_log_path 2>&1 &
+else
+  bash start.sh -t "$team_name" --rpc-port $rpc_port --rpc-type thrift >> $start_log_path 2>&1 &
+fi
+fistart_pid=$!
 
 # Wait for both background processes to finish
 wait $server_pid
-wait $start_pid
+wait $start_pid

utils/logger_utils.py

@@ -0,0 +1,48 @@
+import logging
+import os
+
+
+def setup_logger(name, log_dir, 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 not os.path.exists(log_dir):
+        os.makedirs(log_dir)
+
+    log_file = os.path.join(log_dir, f'{name}.log')
+
+    # 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