diff --git a/CHANGELOG.md b/CHANGELOG.md index beec6d11..63a4bfe8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,7 +25,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Activating dev-mode will change the location where the sessions will be output - by default will output where the PrimAITE repository is located - Refactored all air-space usage to that a new instance of AirSpace is created for each instance of Network. This 1:1 relationship between network and airspace will allow parallelization. - Added notebook to demonstrate use of SubprocVecEnv from SB3 to vectorise environments to speed up training. -- Added a new agent simulation log which are more human friendly than agent action logging. Includes timesteps so that the agent action log can be cross referenced. These Logs are found in simulation_output directory, similar to that of sys_logs and can be enabled in the I/O settings in a yaml configuration file. +- Added a new agent behaviour log which are more human friendly than agent history. These Logs are found in session log directory and can be enabled in the I/O settings in a yaml configuration file. ## [Unreleased] - Made requests fail to reach their target if the node is off diff --git a/src/primaite/game/agent/agent_log.py b/src/primaite/game/agent/agent_log.py index 1e51dcad..62ef4884 100644 --- a/src/primaite/game/agent/agent_log.py +++ b/src/primaite/game/agent/agent_log.py @@ -22,7 +22,7 @@ class AgentLog: """ A Agent Log class is a simple logger dedicated to managing and writing logging updates and information for an agent. - Each log message is written to a file located at: /agent/agent_name.log + Each log message is written to a file located at: /agent_name/agent_name.log """ def __init__(self, agent_name: str): @@ -33,8 +33,28 @@ class AgentLog: """ self.agent_name = agent_name self.current_episode: int = 1 + self.current_timestep: int = 0 self.setup_logger() + @property + def timestep(self) -> int: + """Returns the current timestep. Used for log indexing. + + :return: The current timestep as an Int. + """ + return self.current_timestep + + def update_timestep(self, new_timestep: int): + """ + Updates the self.current_timestep attribute with the given parameter. + + This method is called within .step() to ensure that all instances of Agent Logs + are in sync with one another. + + :param new_timestep: The new timestep. + """ + self.current_timestep = new_timestep + def setup_logger(self): """ Configures the logger for this Agent Log instance. @@ -60,19 +80,19 @@ class AgentLog: def _get_log_path(self) -> Path: """ - Constructs the path for the log file based on the hostname. + Constructs the path for the log file based on the agent name. :return: Path object representing the location of the log file. """ - root = SIM_OUTPUT.path / f"episode_{self.current_episode}" / "agent_logs" / self.agent_name + root = SIM_OUTPUT.agent_behaviour_path / f"episode_{self.current_episode}" / self.agent_name root.mkdir(exist_ok=True, parents=True) return root / f"{self.agent_name}.log" - def _write_to_terminal(self, msg: str, timestep: int, level: str, to_terminal: bool = False): + def _write_to_terminal(self, msg: str, level: str, to_terminal: bool = False): if to_terminal or SIM_OUTPUT.write_agent_log_to_terminal: - print(f"{self.agent_name}: ({timestep}) ({level}) {msg}") + print(f"{self.agent_name}: ({ self.timestep}) ({level}) {msg}") - def debug(self, msg: str, time_step: int, to_terminal: bool = False): + def debug(self, msg: str, to_terminal: bool = False): """ Logs a message with the DEBUG level. @@ -83,10 +103,10 @@ class AgentLog: return if SIM_OUTPUT.save_agent_logs: - self.logger.debug(msg, extra={"timestep": time_step}) + self.logger.debug(msg, extra={"timestep": self.timestep}) self._write_to_terminal(msg, "DEBUG", to_terminal) - def info(self, msg: str, time_step: int, to_terminal: bool = False): + def info(self, msg: str, to_terminal: bool = False): """ Logs a message with the INFO level. @@ -98,10 +118,10 @@ class AgentLog: return if SIM_OUTPUT.save_agent_logs: - self.logger.info(msg, extra={"timestep": time_step}) + self.logger.info(msg, extra={"timestep": self.timestep}) self._write_to_terminal(msg, "INFO", to_terminal) - def warning(self, msg: str, time_step: int, to_terminal: bool = False): + def warning(self, msg: str, to_terminal: bool = False): """ Logs a message with the WARNING level. @@ -113,10 +133,10 @@ class AgentLog: return if SIM_OUTPUT.save_agent_logs: - self.logger.warning(msg, extra={"timestep": time_step}) + self.logger.warning(msg, extra={"timestep": self.timestep}) self._write_to_terminal(msg, "WARNING", to_terminal) - def error(self, msg: str, time_step: int, to_terminal: bool = False): + def error(self, msg: str, to_terminal: bool = False): """ Logs a message with the ERROR level. @@ -128,10 +148,10 @@ class AgentLog: return if SIM_OUTPUT.save_agent_logs: - self.logger.error(msg, extra={"timestep": time_step}) + self.logger.error(msg, extra={"timestep": self.timestep}) self._write_to_terminal(msg, "ERROR", to_terminal) - def critical(self, msg: str, time_step: int, to_terminal: bool = False): + def critical(self, msg: str, to_terminal: bool = False): """ Logs a message with the CRITICAL level. @@ -143,7 +163,7 @@ class AgentLog: return if SIM_OUTPUT.save_agent_logs: - self.logger.critical(msg, extra={"timestep": time_step}) + self.logger.critical(msg, extra={"timestep": self.timestep}) self._write_to_terminal(msg, "CRITICAL", to_terminal) def show(self, last_n: int = 10, markdown: bool = False): diff --git a/src/primaite/game/agent/scripted_agents/data_manipulation_bot.py b/src/primaite/game/agent/scripted_agents/data_manipulation_bot.py index cd72e001..129fac1a 100644 --- a/src/primaite/game/agent/scripted_agents/data_manipulation_bot.py +++ b/src/primaite/game/agent/scripted_agents/data_manipulation_bot.py @@ -38,11 +38,11 @@ class DataManipulationAgent(AbstractScriptedAgent): :rtype: Tuple[str, Dict] """ if timestep < self.next_execution_timestep: - self.logger.debug(msg="Performing do NOTHING", time_step=timestep) + self.logger.debug(msg="Performing do NOTHING") return "DONOTHING", {} self._set_next_execution_timestep(timestep + self.agent_settings.start_settings.frequency) - self.logger.info(msg="Performing a data manipulation attack!", time_step=timestep) + self.logger.info(msg="Performing a data manipulation attack!") return "NODE_APPLICATION_EXECUTE", {"node_id": self.starting_node_idx, "application_id": 0} def setup_agent(self) -> None: @@ -55,4 +55,4 @@ class DataManipulationAgent(AbstractScriptedAgent): # we are assuming that every node in the node manager has a data manipulation application at idx 0 num_nodes = len(self.action_manager.node_names) self.starting_node_idx = random.randint(0, num_nodes - 1) - self.logger.debug(msg=f"Select Start Node ID: {self.starting_node_idx}", time_step=0) + self.logger.debug(msg=f"Select Start Node ID: {self.starting_node_idx}") diff --git a/src/primaite/game/agent/scripted_agents/probabilistic_agent.py b/src/primaite/game/agent/scripted_agents/probabilistic_agent.py index e0f41302..f5905ad0 100644 --- a/src/primaite/game/agent/scripted_agents/probabilistic_agent.py +++ b/src/primaite/game/agent/scripted_agents/probabilistic_agent.py @@ -85,5 +85,5 @@ class ProbabilisticAgent(AbstractScriptedAgent): :rtype: Tuple[str, Dict] """ choice = self.rng.choice(len(self.action_manager.action_map), p=self.probabilities) - self.logger.info(f"Performing Action: {choice}", time_step=timestep) + self.logger.info(f"Performing Action: {choice}") return self.action_manager.get_action(choice) diff --git a/src/primaite/game/game.py b/src/primaite/game/game.py index 3dc9571f..cb787e68 100644 --- a/src/primaite/game/game.py +++ b/src/primaite/game/game.py @@ -15,6 +15,7 @@ from primaite.game.agent.scripted_agents.probabilistic_agent import Probabilisti from primaite.game.agent.scripted_agents.random_agent import PeriodicAgent from primaite.game.agent.scripted_agents.tap001 import TAP001 from primaite.game.science import graph_has_cycle, topological_sort +from primaite.simulator import SIM_OUTPUT from primaite.simulator.network.hardware.base import NodeOperatingState from primaite.simulator.network.hardware.nodes.host.computer import Computer from primaite.simulator.network.hardware.nodes.host.host_node import NIC @@ -164,6 +165,8 @@ class PrimaiteGame: for _, agent in self.agents.items(): obs = agent.observation_manager.current_observation action_choice, parameters = agent.get_action(obs, timestep=self.step_counter) + if SIM_OUTPUT.save_agent_logs: + agent.logger.debug(f"Chosen Action: {action_choice}") request = agent.format_request(action_choice, parameters) response = self.simulation.apply_request(request) agent.process_action_response( @@ -182,8 +185,14 @@ class PrimaiteGame: """Advance timestep.""" self.step_counter += 1 _LOGGER.debug(f"Advancing timestep to {self.step_counter} ") + self.update_agent_loggers() self.simulation.apply_timestep(self.step_counter) + def update_agent_loggers(self) -> None: + """Updates Agent Loggers with new timestep.""" + for agent in self.agents.values(): + agent.logger.update_timestep(self.step_counter) + def calculate_truncated(self) -> bool: """Calculate whether the episode is truncated.""" current_step = self.step_counter diff --git a/src/primaite/session/io.py b/src/primaite/session/io.py index 05a5ee09..78d7cb3c 100644 --- a/src/primaite/session/io.py +++ b/src/primaite/session/io.py @@ -57,6 +57,7 @@ class PrimaiteIO: self.session_path: Path = self.generate_session_path() # set global SIM_OUTPUT path SIM_OUTPUT.path = self.session_path / "simulation_output" + SIM_OUTPUT.agent_behaviour_path = self.session_path / "agent_behaviour" SIM_OUTPUT.save_pcap_logs = self.settings.save_pcap_logs SIM_OUTPUT.save_sys_logs = self.settings.save_sys_logs SIM_OUTPUT.save_agent_logs = self.settings.save_agent_logs @@ -67,20 +68,20 @@ class PrimaiteIO: def generate_session_path(self, timestamp: Optional[datetime] = None) -> Path: """Create a folder for the session and return the path to it.""" - if timestamp is None: - timestamp = datetime.now() - date_str = timestamp.strftime("%Y-%m-%d") - time_str = timestamp.strftime("%H-%M-%S") - - session_path = PRIMAITE_PATHS.user_sessions_path / date_str / time_str + session_path = PRIMAITE_PATHS.user_sessions_path / SIM_OUTPUT.date_str / SIM_OUTPUT.time_str # check if running in dev mode if is_dev_mode(): - session_path = _PRIMAITE_ROOT.parent.parent / "sessions" / date_str / time_str + session_path = _PRIMAITE_ROOT.parent.parent / "sessions" / SIM_OUTPUT.date_str / SIM_OUTPUT.time_str # check if there is an output directory set in config if PRIMAITE_CONFIG["developer_mode"]["output_dir"]: - session_path = Path(PRIMAITE_CONFIG["developer_mode"]["output_dir"]) / "sessions" / date_str / time_str + session_path = ( + Path(PRIMAITE_CONFIG["developer_mode"]["output_dir"]) + / "sessions" + / SIM_OUTPUT.date_str + / SIM_OUTPUT.time_str + ) session_path.mkdir(exist_ok=True, parents=True) return session_path diff --git a/src/primaite/setup/_package_data/primaite_config.yaml b/src/primaite/setup/_package_data/primaite_config.yaml index c1caf1f4..e08d951e 100644 --- a/src/primaite/setup/_package_data/primaite_config.yaml +++ b/src/primaite/setup/_package_data/primaite_config.yaml @@ -3,6 +3,8 @@ developer_mode: enabled: False # not enabled by default sys_log_level: DEBUG # level of output for system logs, DEBUG by default + agent_log_level: DEBUG # level of output for agent logs, DEBUG by default + output_agent_logs: False # level of output for system logs, DEBUG by default output_sys_logs: False # system logs not output by default output_pcap_logs: False # pcap logs not output by default output_to_terminal: False # do not output to terminal by default diff --git a/src/primaite/simulator/__init__.py b/src/primaite/simulator/__init__.py index 487e7c5e..ade1a73b 100644 --- a/src/primaite/simulator/__init__.py +++ b/src/primaite/simulator/__init__.py @@ -34,6 +34,7 @@ class _SimOutput: path = PRIMAITE_PATHS.user_sessions_path / self.date_str / self.time_str self._path = path + self._agent_behaviour_path = path self._save_pcap_logs: bool = False self._save_sys_logs: bool = False self._save_agent_logs: bool = False @@ -64,6 +65,28 @@ class _SimOutput: self._path = new_path self._path.mkdir(exist_ok=True, parents=True) + @property + def agent_behaviour_path(self) -> Path: + if is_dev_mode(): + # if dev mode is enabled, if output dir is not set, print to primaite repo root + path: Path = _PRIMAITE_ROOT.parent.parent / "sessions" / self.date_str / self.time_str / "agent_behaviour" + # otherwise print to output dir + if PRIMAITE_CONFIG["developer_mode"]["output_dir"]: + path: Path = ( + Path(PRIMAITE_CONFIG["developer_mode"]["output_dir"]) + / "sessions" + / self.date_str + / self.time_str + / "agent_behaviour" + ) + self._agent_behaviour_path = path + return self._agent_behaviour_path + + @agent_behaviour_path.setter + def agent_behaviour_path(self, new_path: Path) -> None: + self._agent_behaviour_path = new_path + self._agent_behaviour_path.mkdir(exist_ok=True, parents=True) + @property def save_pcap_logs(self) -> bool: if is_dev_mode(): diff --git a/src/primaite/utils/cli/dev_cli.py b/src/primaite/utils/cli/dev_cli.py index 15adacb3..0dd9f9cc 100644 --- a/src/primaite/utils/cli/dev_cli.py +++ b/src/primaite/utils/cli/dev_cli.py @@ -82,12 +82,31 @@ def config_callback( show_default=False, ), ] = None, + agent_log_level: Annotated[ + LogLevel, + typer.Option( + "--agent-log-level", + "-level", + click_type=click.Choice(LogLevel._member_names_, case_sensitive=False), + help="The level of agent behaviour logs to output.", + show_default=False, + ), + ] = None, output_sys_logs: Annotated[ bool, typer.Option( "--output-sys-logs/--no-sys-logs", "-sys/-nsys", help="Output system logs to file.", show_default=False ), ] = None, + output_agent_logs: Annotated[ + bool, + typer.Option( + "--output-agent-logs/--no-agent-logs", + "-agent/-nagent", + help="Output agent logs to file.", + show_default=False, + ), + ] = None, output_pcap_logs: Annotated[ bool, typer.Option( @@ -109,10 +128,18 @@ def config_callback( PRIMAITE_CONFIG["developer_mode"]["sys_log_level"] = ctx.params.get("sys_log_level") print(f"PrimAITE dev-mode config updated sys_log_level={ctx.params.get('sys_log_level')}") + if ctx.params.get("agent_log_level") is not None: + PRIMAITE_CONFIG["developer_mode"]["agent_log_level"] = ctx.params.get("agent_log_level") + print(f"PrimAITE dev-mode config updated agent_log_level={ctx.params.get('agent_log_level')}") + if output_sys_logs is not None: PRIMAITE_CONFIG["developer_mode"]["output_sys_logs"] = output_sys_logs print(f"PrimAITE dev-mode config updated {output_sys_logs=}") + if output_agent_logs is not None: + PRIMAITE_CONFIG["developer_mode"]["output_agent_logs"] = output_agent_logs + print(f"PrimAITE dev-mode config updated {output_agent_logs=}") + if output_pcap_logs is not None: PRIMAITE_CONFIG["developer_mode"]["output_pcap_logs"] = output_pcap_logs print(f"PrimAITE dev-mode config updated {output_pcap_logs=}") diff --git a/tests/integration_tests/cli/test_dev_cli.py b/tests/integration_tests/cli/test_dev_cli.py index 43f623a5..19559e7c 100644 --- a/tests/integration_tests/cli/test_dev_cli.py +++ b/tests/integration_tests/cli/test_dev_cli.py @@ -67,7 +67,7 @@ def test_dev_mode_config_sys_log_level(): # check defaults assert PRIMAITE_CONFIG["developer_mode"]["sys_log_level"] == "DEBUG" # DEBUG by default - result = cli(["dev-mode", "config", "-level", "WARNING"]) + result = cli(["dev-mode", "config", "--sys-log-level", "WARNING"]) assert "sys_log_level=WARNING" in result.output # should print correct value @@ -78,10 +78,30 @@ def test_dev_mode_config_sys_log_level(): assert "sys_log_level=INFO" in result.output # should print correct value - # config should reflect that log level is WARNING + # config should reflect that log level is INFO assert PRIMAITE_CONFIG["developer_mode"]["sys_log_level"] == "INFO" +def test_dev_mode_config_agent_log_level(): + """Check that the agent log level can be changed via CLI.""" + # check defaults + assert PRIMAITE_CONFIG["developer_mode"]["agent_log_level"] == "DEBUG" # DEBUG by default + + result = cli(["dev-mode", "config", "-level", "WARNING"]) + + assert "agent_log_level=WARNING" in result.output # should print correct value + + # config should reflect that log level is WARNING + assert PRIMAITE_CONFIG["developer_mode"]["agent_log_level"] == "WARNING" + + result = cli(["dev-mode", "config", "--agent-log-level", "INFO"]) + + assert "agent_log_level=INFO" in result.output # should print correct value + + # config should reflect that log level is INFO + assert PRIMAITE_CONFIG["developer_mode"]["agent_log_level"] == "INFO" + + def test_dev_mode_config_sys_logs_enable_disable(): """Test that the system logs output can be enabled or disabled.""" # check defaults @@ -112,6 +132,36 @@ def test_dev_mode_config_sys_logs_enable_disable(): assert PRIMAITE_CONFIG["developer_mode"]["output_sys_logs"] is False +def test_dev_mode_config_agent_logs_enable_disable(): + """Test that the agent logs output can be enabled or disabled.""" + # check defaults + assert PRIMAITE_CONFIG["developer_mode"]["output_agent_logs"] is False # False by default + + result = cli(["dev-mode", "config", "--output-agent-logs"]) + assert "output_agent_logs=True" in result.output # should print correct value + + # config should reflect that output_agent_logs is True + assert PRIMAITE_CONFIG["developer_mode"]["output_agent_logs"] + + result = cli(["dev-mode", "config", "--no-agent-logs"]) + assert "output_agent_logs=False" in result.output # should print correct value + + # config should reflect that output_agent_logs is True + assert PRIMAITE_CONFIG["developer_mode"]["output_agent_logs"] is False + + result = cli(["dev-mode", "config", "-agent"]) + assert "output_agent_logs=True" in result.output # should print correct value + + # config should reflect that output_agent_logs is True + assert PRIMAITE_CONFIG["developer_mode"]["output_agent_logs"] + + result = cli(["dev-mode", "config", "-nagent"]) + assert "output_agent_logs=False" in result.output # should print correct value + + # config should reflect that output_agent_logs is True + assert PRIMAITE_CONFIG["developer_mode"]["output_agent_logs"] is False + + def test_dev_mode_config_pcap_logs_enable_disable(): """Test that the pcap logs output can be enabled or disabled.""" # check defaults diff --git a/tests/unit_tests/_primaite/_game/_agent/test_agent_log.py b/tests/unit_tests/_primaite/_game/_agent/test_agent_log.py index a7932cb7..d61e1a23 100644 --- a/tests/unit_tests/_primaite/_game/_agent/test_agent_log.py +++ b/tests/unit_tests/_primaite/_game/_agent/test_agent_log.py @@ -29,11 +29,11 @@ def test_debug_agent_log_level(agentlog, capsys): test_string = str(uuid4()) - agentlog.debug(msg=test_string, time_step=0) - agentlog.info(msg=test_string, time_step=0) - agentlog.warning(msg=test_string, time_step=0) - agentlog.error(msg=test_string, time_step=0) - agentlog.critical(msg=test_string, time_step=0) + agentlog.debug(msg=test_string) + agentlog.info(msg=test_string) + agentlog.warning(msg=test_string) + agentlog.error(msg=test_string) + agentlog.critical(msg=test_string) captured = "".join(capsys.readouterr()) @@ -52,11 +52,11 @@ def test_info_agent_log_level(agentlog, capsys): test_string = str(uuid4()) - agentlog.debug(msg=test_string, time_step=0) - agentlog.info(msg=test_string, time_step=0) - agentlog.warning(msg=test_string, time_step=0) - agentlog.error(msg=test_string, time_step=0) - agentlog.critical(msg=test_string, time_step=0) + agentlog.debug(msg=test_string) + agentlog.info(msg=test_string) + agentlog.warning(msg=test_string) + agentlog.error(msg=test_string) + agentlog.critical(msg=test_string) captured = "".join(capsys.readouterr()) @@ -75,11 +75,11 @@ def test_warning_agent_log_level(agentlog, capsys): test_string = str(uuid4()) - agentlog.debug(msg=test_string, time_step=0) - agentlog.info(msg=test_string, time_step=0) - agentlog.warning(msg=test_string, time_step=0) - agentlog.error(msg=test_string, time_step=0) - agentlog.critical(msg=test_string, time_step=0) + agentlog.debug(msg=test_string) + agentlog.info(msg=test_string) + agentlog.warning(msg=test_string) + agentlog.error(msg=test_string) + agentlog.critical(msg=test_string) captured = "".join(capsys.readouterr()) @@ -98,11 +98,11 @@ def test_error_agent_log_level(agentlog, capsys): test_string = str(uuid4()) - agentlog.debug(msg=test_string, time_step=0) - agentlog.info(msg=test_string, time_step=0) - agentlog.warning(msg=test_string, time_step=0) - agentlog.error(msg=test_string, time_step=0) - agentlog.critical(msg=test_string, time_step=0) + agentlog.debug(msg=test_string) + agentlog.info(msg=test_string) + agentlog.warning(msg=test_string) + agentlog.error(msg=test_string) + agentlog.critical(msg=test_string) captured = "".join(capsys.readouterr()) @@ -121,11 +121,11 @@ def test_critical_agent_log_level(agentlog, capsys): test_string = str(uuid4()) - agentlog.debug(msg=test_string, time_step=0) - agentlog.info(msg=test_string, time_step=0) - agentlog.warning(msg=test_string, time_step=0) - agentlog.error(msg=test_string, time_step=0) - agentlog.critical(msg=test_string, time_step=0) + agentlog.debug(msg=test_string) + agentlog.info(msg=test_string) + agentlog.warning(msg=test_string) + agentlog.error(msg=test_string) + agentlog.critical(msg=test_string) captured = "".join(capsys.readouterr())