diff --git a/CHANGELOG.md b/CHANGELOG.md index 0ed09b94..2d9aed82 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - **Bandwidth Tracking**: Tracks data transmission across each frequency/channel width pairing. - **Configuration Support for Wireless Routers**: `channel_width` can now be configured in the config file under `wireless_access_point`. - **New Tests**: Added to validate the respect of bandwidth capacities and the correct parsing of airspace configurations from YAML files. +- **New Logging**: 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. ### Changed @@ -59,8 +60,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - 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. - - ## [Unreleased] - Made requests fail to reach their target if the node is off - Added responses to requests diff --git a/docs/source/configuration/io_settings.rst b/docs/source/configuration/io_settings.rst index 82fd7408..1c9585c9 100644 --- a/docs/source/configuration/io_settings.rst +++ b/docs/source/configuration/io_settings.rst @@ -18,8 +18,11 @@ This section configures how PrimAITE saves data during simulation and training. save_step_metadata: False save_pcap_logs: False save_sys_logs: False + save_agent_logs: False write_sys_log_to_terminal: False + write_agent_log_to_terminal: False sys_log_level: WARNING + agent_log_level: INFO ``save_logs`` @@ -57,6 +60,12 @@ Optional. Default value is ``False``. If ``True``, then the log files which contain all node actions during the simulation will be saved. +``save_agent_logs`` +----------------- + +Optional. Default value is ``False``. + +If ``True``, then the log files which contain all human readable agent behaviour during the simulation will be saved. ``write_sys_log_to_terminal`` ----------------------------- @@ -65,16 +74,25 @@ Optional. Default value is ``False``. If ``True``, PrimAITE will print sys log to the terminal. +``write_agent_log_to_terminal`` +----------------------------- -``sys_log_level`` -------------- +Optional. Default value is ``False``. + +If ``True``, PrimAITE will print all human readable agent behaviour logs to the terminal. + + +``sys_log_level & agent_log_level`` +--------------------------------- Optional. Default value is ``WARNING``. -The level of logging that should be visible in the sys logs or the logs output to the terminal. +The level of logging that should be visible in the syslog, agent logs or the logs output to the terminal. ``save_sys_logs`` or ``write_sys_log_to_terminal`` has to be set to ``True`` for this setting to be used. +This is also true for agent behaviour logging. + Available options are: - ``DEBUG``: Debug level items and the items below diff --git a/src/primaite/game/agent/agent_log.py b/src/primaite/game/agent/agent_log.py new file mode 100644 index 00000000..62ef4884 --- /dev/null +++ b/src/primaite/game/agent/agent_log.py @@ -0,0 +1,188 @@ +# © Crown-owned copyright 2024, Defence Science and Technology Laboratory UK +import logging +from pathlib import Path + +from prettytable import MARKDOWN, PrettyTable + +from primaite.simulator import LogLevel, SIM_OUTPUT + + +class _NotJSONFilter(logging.Filter): + def filter(self, record: logging.LogRecord) -> bool: + """ + Determines if a log message does not start and end with '{' and '}' (i.e., it is not a JSON-like message). + + :param record: LogRecord object containing all the information pertinent to the event being logged. + :return: True if log message is not JSON-like, False otherwise. + """ + return not record.getMessage().startswith("{") and not record.getMessage().endswith("}") + + +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_name/agent_name.log + """ + + def __init__(self, agent_name: str): + """ + Constructs a Agent Log instance for a given hostname. + + :param hostname: The hostname associated with the system logs being recorded. + """ + 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. + + The logger is set to the DEBUG level, and is equipped with a handler that writes to a file and filters out + JSON-like messages. + """ + if not SIM_OUTPUT.save_agent_logs: + return + + log_path = self._get_log_path() + file_handler = logging.FileHandler(filename=log_path) + file_handler.setLevel(logging.DEBUG) + + log_format = "%(timestep)s::%(levelname)s::%(message)s" + file_handler.setFormatter(logging.Formatter(log_format)) + + self.logger = logging.getLogger(f"{self.agent_name}_log") + for handler in self.logger.handlers: + self.logger.removeHandler(handler) + self.logger.setLevel(logging.DEBUG) + self.logger.addHandler(file_handler) + + def _get_log_path(self) -> Path: + """ + 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.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, level: str, to_terminal: bool = False): + if to_terminal or SIM_OUTPUT.write_agent_log_to_terminal: + print(f"{self.agent_name}: ({ self.timestep}) ({level}) {msg}") + + def debug(self, msg: str, to_terminal: bool = False): + """ + Logs a message with the DEBUG level. + + :param msg: The message to be logged. + :param to_terminal: If True, prints to the terminal too. + """ + if SIM_OUTPUT.agent_log_level > LogLevel.DEBUG: + return + + if SIM_OUTPUT.save_agent_logs: + self.logger.debug(msg, extra={"timestep": self.timestep}) + self._write_to_terminal(msg, "DEBUG", to_terminal) + + def info(self, msg: str, to_terminal: bool = False): + """ + Logs a message with the INFO level. + + :param msg: The message to be logged. + :param timestep: The current timestep. + :param to_terminal: If True, prints to the terminal too. + """ + if SIM_OUTPUT.agent_log_level > LogLevel.INFO: + return + + if SIM_OUTPUT.save_agent_logs: + self.logger.info(msg, extra={"timestep": self.timestep}) + self._write_to_terminal(msg, "INFO", to_terminal) + + def warning(self, msg: str, to_terminal: bool = False): + """ + Logs a message with the WARNING level. + + :param msg: The message to be logged. + :param timestep: The current timestep. + :param to_terminal: If True, prints to the terminal too. + """ + if SIM_OUTPUT.agent_log_level > LogLevel.WARNING: + return + + if SIM_OUTPUT.save_agent_logs: + self.logger.warning(msg, extra={"timestep": self.timestep}) + self._write_to_terminal(msg, "WARNING", to_terminal) + + def error(self, msg: str, to_terminal: bool = False): + """ + Logs a message with the ERROR level. + + :param msg: The message to be logged. + :param timestep: The current timestep. + :param to_terminal: If True, prints to the terminal too. + """ + if SIM_OUTPUT.agent_log_level > LogLevel.ERROR: + return + + if SIM_OUTPUT.save_agent_logs: + self.logger.error(msg, extra={"timestep": self.timestep}) + self._write_to_terminal(msg, "ERROR", to_terminal) + + def critical(self, msg: str, to_terminal: bool = False): + """ + Logs a message with the CRITICAL level. + + :param msg: The message to be logged. + :param timestep: The current timestep. + :param to_terminal: If True, prints to the terminal too. + """ + if LogLevel.CRITICAL < SIM_OUTPUT.agent_log_level: + return + + if SIM_OUTPUT.save_agent_logs: + 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): + """ + Print an Agents Log as a table. + + Generate and print PrettyTable instance that shows the agents behaviour log, with columns Time step, + Level and Message. + + :param markdown: Use Markdown style in table output. Defaults to False. + """ + table = PrettyTable(["Time Step", "Level", "Message"]) + if markdown: + table.set_style(MARKDOWN) + table.align = "l" + table.title = f"{self.agent_name} Behaviour Log" + if self._get_log_path().exists(): + with open(self._get_log_path()) as file: + lines = file.readlines() + for line in lines[-last_n:]: + table.add_row(line.strip().split("::")) + print(table) diff --git a/src/primaite/game/agent/interface.py b/src/primaite/game/agent/interface.py index 95468331..c53b1956 100644 --- a/src/primaite/game/agent/interface.py +++ b/src/primaite/game/agent/interface.py @@ -7,6 +7,7 @@ from gymnasium.core import ActType, ObsType from pydantic import BaseModel, model_validator from primaite.game.agent.actions import ActionManager +from primaite.game.agent.agent_log import AgentLog from primaite.game.agent.observations.observation_manager import ObservationManager from primaite.game.agent.rewards import RewardFunction from primaite.interface.request import RequestFormat, RequestResponse @@ -116,6 +117,7 @@ class AbstractAgent(ABC): self.reward_function: Optional[RewardFunction] = reward_function self.agent_settings = agent_settings or AgentSettings() self.history: List[AgentHistoryItem] = [] + self.logger = AgentLog(agent_name) def update_observation(self, state: Dict) -> ObsType: """ 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 3a91f1fe..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,10 +38,11 @@ class DataManipulationAgent(AbstractScriptedAgent): :rtype: Tuple[str, Dict] """ if timestep < self.next_execution_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!") return "NODE_APPLICATION_EXECUTE", {"node_id": self.starting_node_idx, "application_id": 0} def setup_agent(self) -> None: @@ -54,3 +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}") diff --git a/src/primaite/game/agent/scripted_agents/probabilistic_agent.py b/src/primaite/game/agent/scripted_agents/probabilistic_agent.py index fc168687..f5905ad0 100644 --- a/src/primaite/game/agent/scripted_agents/probabilistic_agent.py +++ b/src/primaite/game/agent/scripted_agents/probabilistic_agent.py @@ -85,4 +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}") return self.action_manager.get_action(choice) diff --git a/src/primaite/game/game.py b/src/primaite/game/game.py index dc79bd7e..1e6aeae0 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.airspace import AirspaceEnvironmentType from primaite.simulator.network.hardware.base import NodeOperatingState from primaite.simulator.network.hardware.nodes.host.computer import Computer @@ -165,6 +166,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( @@ -183,8 +186,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 7bfd16f1..78d7cb3c 100644 --- a/src/primaite/session/io.py +++ b/src/primaite/session/io.py @@ -35,10 +35,16 @@ class PrimaiteIO: """Whether to save PCAP logs.""" save_sys_logs: bool = True """Whether to save system logs.""" + save_agent_logs: bool = True + """Whether to save agent logs.""" write_sys_log_to_terminal: bool = False """Whether to write the sys log to the terminal.""" + write_agent_log_to_terminal: bool = False + """Whether to write the agent log to the terminal.""" sys_log_level: LogLevel = LogLevel.INFO - """The level of log that should be included in the logfiles/logged into terminal.""" + """The level of sys logs that should be included in the logfiles/logged into terminal.""" + agent_log_level: LogLevel = LogLevel.INFO + """The level of agent logs that should be included in the logfiles/logged into terminal.""" def __init__(self, settings: Optional[Settings] = None) -> None: """ @@ -51,27 +57,31 @@ 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 + SIM_OUTPUT.write_agent_log_to_terminal = self.settings.write_agent_log_to_terminal SIM_OUTPUT.write_sys_log_to_terminal = self.settings.write_sys_log_to_terminal SIM_OUTPUT.sys_log_level = self.settings.sys_log_level + SIM_OUTPUT.agent_log_level = self.settings.agent_log_level 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 @@ -115,6 +125,9 @@ class PrimaiteIO: if config.get("sys_log_level"): config["sys_log_level"] = LogLevel[config["sys_log_level"].upper()] # convert to enum + if config.get("agent_log_level"): + config["agent_log_level"] = LogLevel[config["agent_log_level"].upper()] # convert to enum + new = cls(settings=cls.Settings(**config)) return new 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 e5fe3cb7..ade1a73b 100644 --- a/src/primaite/simulator/__init__.py +++ b/src/primaite/simulator/__init__.py @@ -34,10 +34,14 @@ 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 self._write_sys_log_to_terminal: bool = False + self._write_agent_log_to_terminal: bool = False self._sys_log_level: LogLevel = LogLevel.WARNING # default log level is at WARNING + self._agent_log_level: LogLevel = LogLevel.WARNING @property def path(self) -> Path: @@ -61,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(): @@ -81,6 +107,16 @@ class _SimOutput: def save_sys_logs(self, save_sys_logs: bool) -> None: self._save_sys_logs = save_sys_logs + @property + def save_agent_logs(self) -> bool: + if is_dev_mode(): + return PRIMAITE_CONFIG.get("developer_mode").get("output_agent_logs") + return self._save_agent_logs + + @save_agent_logs.setter + def save_agent_logs(self, save_agent_logs: bool) -> None: + self._save_agent_logs = save_agent_logs + @property def write_sys_log_to_terminal(self) -> bool: if is_dev_mode(): @@ -91,6 +127,17 @@ class _SimOutput: def write_sys_log_to_terminal(self, write_sys_log_to_terminal: bool) -> None: self._write_sys_log_to_terminal = write_sys_log_to_terminal + # Should this be separate from sys_log? + @property + def write_agent_log_to_terminal(self) -> bool: + if is_dev_mode(): + return PRIMAITE_CONFIG.get("developer_mode").get("output_to_terminal") + return self._write_agent_log_to_terminal + + @write_agent_log_to_terminal.setter + def write_agent_log_to_terminal(self, write_agent_log_to_terminal: bool) -> None: + self._write_agent_log_to_terminal = write_agent_log_to_terminal + @property def sys_log_level(self) -> LogLevel: if is_dev_mode(): @@ -101,5 +148,15 @@ class _SimOutput: def sys_log_level(self, sys_log_level: LogLevel) -> None: self._sys_log_level = sys_log_level + @property + def agent_log_level(self) -> LogLevel: + if is_dev_mode(): + return LogLevel[PRIMAITE_CONFIG.get("developer_mode").get("agent_log_level")] + return self._agent_log_level + + @agent_log_level.setter + def agent_log_level(self, agent_log_level: LogLevel) -> None: + self._agent_log_level = agent_log_level + SIM_OUTPUT = _SimOutput() 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/assets/configs/basic_switched_network.yaml b/tests/assets/configs/basic_switched_network.yaml index 7d40075d..69187fa3 100644 --- a/tests/assets/configs/basic_switched_network.yaml +++ b/tests/assets/configs/basic_switched_network.yaml @@ -9,6 +9,9 @@ io_settings: save_pcap_logs: true save_sys_logs: true sys_log_level: WARNING + agent_log_level: INFO + save_agent_logs: true + write_agent_log_to_terminal: True game: 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/integration_tests/configuration_file_parsing/test_io_settings.py b/tests/integration_tests/configuration_file_parsing/test_io_settings.py index ebaa4956..82977b82 100644 --- a/tests/integration_tests/configuration_file_parsing/test_io_settings.py +++ b/tests/integration_tests/configuration_file_parsing/test_io_settings.py @@ -35,3 +35,7 @@ def test_io_settings(): assert env.io.settings.save_step_metadata is False assert env.io.settings.write_sys_log_to_terminal is False # false by default + + assert env.io.settings.save_agent_logs is True + assert env.io.settings.agent_log_level is LogLevel.INFO + assert env.io.settings.write_agent_log_to_terminal is True # Set to True by the config file. diff --git a/tests/unit_tests/_primaite/_game/_agent/test_agent_log.py b/tests/unit_tests/_primaite/_game/_agent/test_agent_log.py new file mode 100644 index 00000000..d61e1a23 --- /dev/null +++ b/tests/unit_tests/_primaite/_game/_agent/test_agent_log.py @@ -0,0 +1,137 @@ +# © Crown-owned copyright 2024, Defence Science and Technology Laboratory UK +from uuid import uuid4 + +import pytest + +from primaite import PRIMAITE_CONFIG +from primaite.game.agent.agent_log import AgentLog +from primaite.simulator import LogLevel, SIM_OUTPUT + + +@pytest.fixture(autouse=True) +def override_dev_mode_temporarily(): + """Temporarily turn off dev mode for this test.""" + primaite_dev_mode = PRIMAITE_CONFIG["developer_mode"]["enabled"] + PRIMAITE_CONFIG["developer_mode"]["enabled"] = False + yield # run tests + PRIMAITE_CONFIG["developer_mode"]["enabled"] = primaite_dev_mode + + +@pytest.fixture(scope="function") +def agentlog() -> AgentLog: + return AgentLog(agent_name="test_agent") + + +def test_debug_agent_log_level(agentlog, capsys): + """Test that the debug log level logs debug agent logs and above.""" + SIM_OUTPUT.agent_log_level = LogLevel.DEBUG + SIM_OUTPUT.write_agent_log_to_terminal = True + + test_string = str(uuid4()) + + 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()) + + assert test_string in captured + assert "DEBUG" in captured + assert "INFO" in captured + assert "WARNING" in captured + assert "ERROR" in captured + assert "CRITICAL" in captured + + +def test_info_agent_log_level(agentlog, capsys): + """Test that the debug log level logs debug agent logs and above.""" + SIM_OUTPUT.agent_log_level = LogLevel.INFO + SIM_OUTPUT.write_agent_log_to_terminal = True + + test_string = str(uuid4()) + + 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()) + + assert test_string in captured + assert "DEBUG" not in captured + assert "INFO" in captured + assert "WARNING" in captured + assert "ERROR" in captured + assert "CRITICAL" in captured + + +def test_warning_agent_log_level(agentlog, capsys): + """Test that the debug log level logs debug agent logs and above.""" + SIM_OUTPUT.agent_log_level = LogLevel.WARNING + SIM_OUTPUT.write_agent_log_to_terminal = True + + test_string = str(uuid4()) + + 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()) + + assert test_string in captured + assert "DEBUG" not in captured + assert "INFO" not in captured + assert "WARNING" in captured + assert "ERROR" in captured + assert "CRITICAL" in captured + + +def test_error_agent_log_level(agentlog, capsys): + """Test that the debug log level logs debug agent logs and above.""" + SIM_OUTPUT.agent_log_level = LogLevel.ERROR + SIM_OUTPUT.write_agent_log_to_terminal = True + + test_string = str(uuid4()) + + 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()) + + assert test_string in captured + assert "DEBUG" not in captured + assert "INFO" not in captured + assert "WARNING" not in captured + assert "ERROR" in captured + assert "CRITICAL" in captured + + +def test_critical_agent_log_level(agentlog, capsys): + """Test that the debug log level logs debug agent logs and above.""" + SIM_OUTPUT.agent_log_level = LogLevel.CRITICAL + SIM_OUTPUT.write_agent_log_to_terminal = True + + test_string = str(uuid4()) + + 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()) + + assert test_string in captured + assert "DEBUG" not in captured + assert "INFO" not in captured + assert "WARNING" not in captured + assert "ERROR" not in captured + assert "CRITICAL" in captured