diff --git a/CHANGELOG.md b/CHANGELOG.md index 17bf3557..beec6d11 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,8 +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. ## [Unreleased] - Made requests fail to reach their target if the node is off 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..1e51dcad --- /dev/null +++ b/src/primaite/game/agent/agent_log.py @@ -0,0 +1,168 @@ +# © 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/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.setup_logger() + + 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 hostname. + + :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.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): + if to_terminal or SIM_OUTPUT.write_agent_log_to_terminal: + print(f"{self.agent_name}: ({timestep}) ({level}) {msg}") + + def debug(self, msg: str, time_step: int, 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": time_step}) + self._write_to_terminal(msg, "DEBUG", to_terminal) + + def info(self, msg: str, time_step: int, 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": time_step}) + self._write_to_terminal(msg, "INFO", to_terminal) + + def warning(self, msg: str, time_step: int, 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": time_step}) + self._write_to_terminal(msg, "WARNING", to_terminal) + + def error(self, msg: str, time_step: int, 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": time_step}) + self._write_to_terminal(msg, "ERROR", to_terminal) + + def critical(self, msg: str, time_step: int, 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": time_step}) + 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..cd72e001 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", time_step=timestep) 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) 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}", time_step=0) diff --git a/src/primaite/game/agent/scripted_agents/probabilistic_agent.py b/src/primaite/game/agent/scripted_agents/probabilistic_agent.py index fc168687..e0f41302 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}", time_step=timestep) return self.action_manager.get_action(choice) diff --git a/src/primaite/session/io.py b/src/primaite/session/io.py index 7bfd16f1..05a5ee09 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: """ @@ -53,8 +59,11 @@ class PrimaiteIO: SIM_OUTPUT.path = self.session_path / "simulation_output" 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.""" @@ -115,6 +124,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/simulator/__init__.py b/src/primaite/simulator/__init__.py index e5fe3cb7..487e7c5e 100644 --- a/src/primaite/simulator/__init__.py +++ b/src/primaite/simulator/__init__.py @@ -36,8 +36,11 @@ class _SimOutput: self._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: @@ -81,6 +84,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 +104,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 +125,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/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/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..a7932cb7 --- /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, 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) + + 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, 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) + + 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, 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) + + 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, 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) + + 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, 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) + + 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