adding private_src env example script and expanded debug logging

CHANGELOG.md

@@ -16,6 +16,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - `private_src` directory to hold all compiled and/or obfuscated source code (e.g. to obfuscate bot policies in environments)
 - 'lg3_envs.py` that use ilqgames-based Guard agent
 - 'matplotlib' dependency for testing group
+- `scripts/example_private_src_env_runner.py` as an example of running and debugging private-source, advanced-bot environment `LBG1_LG3_I2_V1`
 
 ### Fixed
 
@@ -24,6 +25,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ### Changed
 
 - Updated `example_eval_cfg.yaml` and related instructions in README to point to the private-source LBG1_LG3_I2_V1 environment
+- Expanded DEBUG logger for better introspection on thread execution
 
 ### Removed
 

README.md

@@ -322,6 +322,15 @@ Therefore we have defined a Agent-Environment Runner class that helps manage the
 
 See [`scripts/example_agent_runner.py`](scripts/example_agent_runner.py) for more details
 
+Some environments have obfuscated source code with more advanced bots. To here is an example of running a simple agent within such an environment (note that you load `lbg1_i2` mission instead of `pe1_i3`)
+
+1. Start KSP game application. 
+2. Select `Start Game` > `Play Missions` > `Community Created` > `lbg1_i2` > `Continue`
+3. In kRPC dialog box click `Add server`. Select `Show advanced settings` and select `Auto-accept new clients`. Then select `Start Server`
+4. In a terminal, run `python scripts/example_private_src_env_runner.py`
+
+See [`scripts/example_private_src_env_runner.py`](scripts/example_private_src_env_runner.py) for more details
+
 ------------
 
 ## Example: Agent-Environment Evaluator for SciTech Challenge

scripts/example_private_src_env_runner.py

@@ -0,0 +1,48 @@
+# Copyright (c) 2024, MASSACHUSETTS INSTITUTE OF TECHNOLOGY
+# Subject to FAR 52.227-11 – Patent Rights – Ownership by the Contractor (May 2014).
+# SPDX-License-Identifier: MIT
+
+"""
+This example shows how to run a basic agent within a private-source environment w/ advanced bots
+
+Instructions to Run:
+- Start KSP game application.
+- Select Start Game > Play Missions > Community Created > lbg1_i2 > Continue
+- In kRPC dialog box click Add server. Select Show advanced settings and select Auto-accept new clients. Then select Start Server
+- In a terminal, run this script
+
+"""
+
+from kspdg.agent_api.base_agent import KSPDGBaseAgent
+from kspdg import LBG1_LG3_I2_V1
+from kspdg.agent_api.runner import AgentEnvRunner
+
+class NaivePursuitAgent(KSPDGBaseAgent):
+    """An agent that naively burns directly toward it's target"""
+    def __init__(self):
+        super().__init__()
+
+    def get_action(self, observation):
+        """ compute agent's action given observation
+
+        This function is necessary to define as it overrides 
+        an abstract method
+        """
+
+        return {
+            "burn_vec": [1.0, 0, 0, 1.0], # throttle in x-axis, throttle in y-axis, throttle in z-axis, duration [s]
+            "ref_frame": 0  # burn_vec expressed in agent vessel's right-handed body frame. 
+                            # i.e. forward throttle, right throttle, down throttle, 
+                            # Can also use rhcbci (1) and rhntw (2) ref frames
+        }
+
+if __name__ == "__main__":
+    naive_agent = NaivePursuitAgent()    
+    runner = AgentEnvRunner(
+        agent=naive_agent, 
+        env_cls=LBG1_LG3_I2_V1, 
+        env_kwargs=None,
+        runner_timeout=100,     # agent runner that will timeout after 100 seconds
+        debug=True)
+    print(runner.run())
+

src/kspdg/agent_api/ksp_interface.py

@@ -3,6 +3,7 @@
 # SPDX-License-Identifier: MIT
 
 import logging
+import time
 
 from kspdg.utils.loggers import create_logger
 
@@ -70,7 +71,12 @@ def observation_handshake():
             continue
 
         # execute agent's action in KSP environment
+        if debug:
+            env_step_start = time.time()
+            logger.debug("Stepping environment...")
         _, _, env_done, env_info = env.step(action=agent_act)
+        if debug:
+            logger.debug(f"Environment step completed in {time.time()-env_step_start:.5g} sec")
 
         # terminate agent runner loops if environment flags a done episode
         if env_done:

src/kspdg/agent_api/runner.py

@@ -118,7 +118,9 @@ def policy_loop(self):
         while not self.termination_event.is_set():
 
             # request/receive observation from environment
-            self.logger.debug("Requesting new environment observation")
+            if self.debug:
+                obs_req_time = time.time()
+                self.logger.debug("Requesting new environment observation")
             self.observation_query_event.set()
             if self.obs_conn_recv.poll(timeout=self.OBSERVATION_POLL_TIMEOUT):
                 try:
@@ -134,6 +136,8 @@ def policy_loop(self):
                 self.logger.info("Non-responsive environment, terminating agent...")
                 self.termination_event.set()
                 break
+            if self.debug:
+                self.logger.debug(f"Environment observation received after {time.time()-obs_req_time:.5g} sec")
 
             # compute agent-specific action and send to env interface process
             action = self.agent.get_action(observation=observation)

src/kspdg/base_envs.py

@@ -34,6 +34,7 @@ def __init__(self, debug:bool=False) -> None:
 
         # create logger to store environment metrics
         # use environment child class name for more specificity on origin of log statements
+        self.debug = debug
         self.logger = create_logger(
             self.__class__.__name__, 
             stream_log_level=logging.DEBUG if debug else logging.INFO)
@@ -105,7 +106,7 @@ def _start_bot_threads(self) -> None:
                 raise ConnectionError("bot_thread is already running."+ 
                     " Close and join bot_thread before restarting")
 
-        self.bot_thread = Thread(target=self.bot_policy)
+        self.bot_thread = Thread(target=self.bot_policy, name='BotThread')
         self.bot_thread.start()
 
     def _start_episode_termination_thread(self) -> None:
@@ -119,7 +120,7 @@ def _start_episode_termination_thread(self) -> None:
                 raise ConnectionError("episode_termination_thread is already running."+ 
                     " Close and join episode_termination_thread before restarting")
 
-        self.episode_termination_thread = Thread(target=self.enforce_episode_termination)
+        self.episode_termination_thread = Thread(target=self.enforce_episode_termination, name="TerminationThread")
         self.episode_termination_thread.start()
 
     def close(self):
@@ -341,8 +342,10 @@ def vessel_step(self, action: Dict, vesAgent):
                 krpc Vessel object for vessel that is acting as the agent (as opposed to pre-scripted bot vessels)
         
         """
-
-        # raise NotImplementedError("Exand action space to include units and add corresponding logic")
+
+        if self.debug:
+            vessel_step_start = time.time()
+            self.logger.debug("Beginning vessel_step...")
 
         k_burn_vec = self.PARAMS.ACTION.K_BURN_VEC
         k_vec_type = self.PARAMS.ACTION.K_VEC_TYPE
@@ -402,28 +405,35 @@ def vessel_step(self, action: Dict, vesAgent):
 
         # execute maneuver for specified time, checking for end
         # conditions while you do
+        if self.debug:
+            self.logger.debug(f"vessel_step (t+{time.time()-vessel_step_start:.5g}) - Beginning vessel_step burn for {burn_dur:.5g} sec")
         timeout = time.time() + burn_dur
         while True: 
             if self.is_episode_done or time.time() > timeout:
                 break
+        self.logger.debug(f"vessel_step (t+{time.time()-vessel_step_start:.5g}) - Burn complete, zeroing thrust")
 
         # zero out thrusts
         vesAgent.control.forward = 0.0
         vesAgent.control.up = 0.0
         vesAgent.control.right = 0.0
 
         # get observation
+        self.logger.debug(f"vessel_step (t+{time.time()-vessel_step_start:.5g}) - querying environment observation for info processing")
         obs = self.get_observation()
 
         # compute performance metrics
+        self.logger.debug(f"vessel_step (t+{time.time()-vessel_step_start:.5g}) - processing env info")
         info = self.get_info(obs, self.is_episode_done)
 
         # display weighted score
-        print("CURRENT SCORE: {}".format(info[self.PARAMS.INFO.K_WEIGHTED_SCORE]))
+        self.logger.info(f"CURRENT SCORE: {info[self.PARAMS.INFO.K_WEIGHTED_SCORE]}")
 
         # compute reward
+        self.logger.debug(f"vessel_step (t+{time.time()-vessel_step_start:.5g}) - computing reward value")
         rew = self.get_reward(info, self.is_episode_done)
 
+        self.logger.debug(f"vessel_step (t+{time.time()-vessel_step_start:.5g}) - vessel_step complete")
         return obs, rew, self.is_episode_done, info
 
     def get_burn__rhvbody(self, burn_vec, ref_frame, vesAgent):

src/kspdg/lbg1/lbg1_base.py

@@ -373,6 +373,8 @@ def get_observation(self) -> ArrayLike:
 
         '''
 
+        self.logger.debug("Starting get_observation ...")
+
         rf = self.vesBandit.orbit.body.non_rotating_reference_frame
 
         obs = [None] * self.PARAMS.OBSERVATION.LEN
@@ -429,6 +431,8 @@ def get_observation(self) -> ArrayLike:
             obs[self.PARAMS.OBSERVATION.I_GUARD_VY], \
             obs[self.PARAMS.OBSERVATION.I_GUARD_VZ]  = \
             v_g_cb__rhcbci
+
+        self.logger.debug("get_observation complete")
 
         return np.array(obs)
 

src/kspdg/utils/loggers.py

@@ -33,7 +33,7 @@ def create_logger(
     c_handler.setLevel(stream_log_level)
 
     # Create formatters and add it to handlers
-    c_format = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
+    c_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - [%(threadName)s] - %(message)s')
     c_handler.setFormatter(c_format)
 
     # Add handlers to the logger