Turning some logger.info into logger.debug and remove some logging overhead when not using debug (#5211)

* turning some logger.info into logger.debug and remove some logging overhead when not using debug

* Addressing comments

* Adding to changelog

Author: vincentpierre

com.unity.ml-agents/CHANGELOG.md

@@ -43,6 +43,7 @@ depend on the previous behavior, you can explicitly set the Agent's `InferenceDe
  - Modified the [GridWorld environment](https://github.com/Unity-Technologies/ml-agents/blob/main/docs/Learning-Environment-Examples.md#gridworld) to use the new `Goal Signal` feature. (#5193)
 
 #### ml-agents / ml-agents-envs / gym-unity (Python)
+- Some console output have been moved from `info` to `debug` and will not be printed by default. If you want all messages to be printed, you can run `mlagents-learn` with the `--debug` option or add the line `debug: true` at the top of the yaml config file. (#5211)
 
 ### Bug Fixes
 #### com.unity.ml-agents / com.unity.ml-agents.extensions (C#)

ml-agents-envs/mlagents_envs/environment.py

@@ -279,7 +279,7 @@ def _update_behavior_specs(self, output: UnityOutputProto) -> None:
                 agent = agent_infos.value[0]
                 new_spec = behavior_spec_from_proto(brain_param, agent)
                 self._env_specs[brain_param.brain_name] = new_spec
-                logger.info(f"Connected new brain:\n{brain_param.brain_name}")
+                logger.info(f"Connected new brain: {brain_param.brain_name}")
 
     def _update_state(self, output: UnityRLOutputProto) -> None:
         """
@@ -426,9 +426,9 @@ def _close(self, timeout: Optional[int] = None) -> None:
             # Wait a bit for the process to shutdown, but kill it if it takes too long
             try:
                 self._process.wait(timeout=timeout)
-                logger.info(self._returncode_to_env_message(self._process.returncode))
+                logger.debug(self._returncode_to_env_message(self._process.returncode))
             except subprocess.TimeoutExpired:
-                logger.info("Environment timed out shutting down. Killing...")
+                logger.warning("Environment timed out shutting down. Killing...")
                 self._process.kill()
             # Set to None so we don't try to close multiple times.
             self._process = None

ml-agents-envs/mlagents_envs/logging_util.py

@@ -12,7 +12,8 @@
 _loggers = set()
 _log_level = NOTSET
 DATE_FORMAT = "%Y-%m-%d %H:%M:%S"
-LOG_FORMAT = "%(asctime)s %(levelname)s [%(filename)s:%(lineno)d] %(message)s"
+DEBUG_LOG_FORMAT = "%(asctime)s %(levelname)s [%(filename)s:%(lineno)d] %(message)s"
+LOG_FORMAT = "[%(levelname)s] %(message)s"
 
 
 def get_logger(name: str) -> logging.Logger:
@@ -21,15 +22,19 @@ def get_logger(name: str) -> logging.Logger:
     specified by set_log_level()
     """
     logger = logging.getLogger(name=name)
-    # If we've already set the log level, make sure new loggers use it
-    if _log_level != NOTSET:
-        logger.setLevel(_log_level)
 
+    if _log_level == DEBUG:
+        formatter = logging.Formatter(fmt=DEBUG_LOG_FORMAT, datefmt=DATE_FORMAT)
+    else:
+        formatter = logging.Formatter(fmt=LOG_FORMAT)
     handler = logging.StreamHandler(stream=sys.stdout)
-    formatter = logging.Formatter(fmt=LOG_FORMAT, datefmt=DATE_FORMAT)
     handler.setFormatter(formatter)
     logger.addHandler(handler)
 
+    # If we've already set the log level, make sure new loggers use it
+    if _log_level != NOTSET:
+        logger.setLevel(_log_level)
+
     # Keep track of this logger so that we can change the log level later
     _loggers.add(logger)
     return logger
@@ -44,3 +49,15 @@ def set_log_level(log_level: int) -> None:
 
     for logger in _loggers:
         logger.setLevel(log_level)
+
+    if log_level == DEBUG:
+        formatter = logging.Formatter(fmt=DEBUG_LOG_FORMAT, datefmt=DATE_FORMAT)
+    else:
+        formatter = logging.Formatter(LOG_FORMAT)
+    _set_formatter_for_all_loggers(formatter)
+
+
+def _set_formatter_for_all_loggers(formatter: logging.Formatter) -> None:
+    for logger in _loggers:
+        for handler in logger.handlers[:]:
+            handler.setFormatter(formatter)

ml-agents/mlagents/torch_utils/torch.py

@@ -55,7 +55,7 @@ def set_torch_config(torch_settings: TorchSettings) -> None:
         torch.set_default_tensor_type(torch.cuda.FloatTensor)
     else:
         torch.set_default_tensor_type(torch.FloatTensor)
-    logger.info(f"default Torch device: {_device}")
+    logger.debug(f"default Torch device: {_device}")
 
 
 # Initialize to default settings

ml-agents/mlagents/trainers/learn.py

@@ -242,7 +242,7 @@ def run_cli(options: RunOptions) -> None:
 
     if options.env_settings.seed == -1:
         run_seed = np.random.randint(0, 10000)
-        logger.info(f"run_seed set to {run_seed}")
+        logger.debug(f"run_seed set to {run_seed}")
     run_training(run_seed, options)
 
 

ml-agents/mlagents/trainers/policy/checkpoint_manager.py

@@ -40,9 +40,9 @@ def remove_checkpoint(checkpoint: Dict[str, Any]) -> None:
         file_path: str = checkpoint["file_path"]
         if os.path.exists(file_path):
             os.remove(file_path)
-            logger.info(f"Removed checkpoint model {file_path}.")
+            logger.debug(f"Removed checkpoint model {file_path}.")
         else:
-            logger.info(f"Checkpoint at {file_path} could not be found.")
+            logger.debug(f"Checkpoint at {file_path} could not be found.")
         return
 
     @classmethod

ml-agents/mlagents/trainers/sac/trainer.py

@@ -116,10 +116,10 @@ def load_replay_buffer(self) -> None:
         Loads the last saved replay buffer from a file.
         """
         filename = os.path.join(self.artifact_path, "last_replay_buffer.hdf5")
-        logger.info(f"Loading Experience Replay Buffer from {filename}")
+        logger.info(f"Loading Experience Replay Buffer from {filename}...")
         with open(filename, "rb+") as file_object:
             self.update_buffer.load_from_file(file_object)
-        logger.info(
+        logger.debug(
             "Experience replay buffer has {} experiences.".format(
                 self.update_buffer.num_experiences
             )

ml-agents/mlagents/trainers/stats.py

@@ -235,13 +235,14 @@ def _delete_all_events_files(self, directory_name: str) -> None:
         for file_name in os.listdir(directory_name):
             if file_name.startswith("events.out"):
                 logger.warning(
-                    f"{file_name} was left over from a previous run. Deleting."
+                    f"Deleting TensorBoard data {file_name} that was left over from a"
+                    "previous run."
                 )
                 full_fname = os.path.join(directory_name, file_name)
                 try:
                     os.remove(full_fname)
                 except OSError:
-                    logger.warning(
+                    logger.error(
                         "{} was left over from a previous run and "
                         "not deleted.".format(full_fname)
                     )

ml-agents/mlagents/trainers/subprocess_env_manager.py

@@ -217,7 +217,7 @@ def _generate_all_results() -> AllStepResult:
         UnityEnvironmentException,
         UnityCommunicatorStoppedException,
     ) as ex:
-        logger.info(f"UnityEnvironment worker {worker_id}: environment stopping.")
+        logger.debug(f"UnityEnvironment worker {worker_id}: environment stopping.")
         step_queue.put(
             EnvironmentResponse(EnvironmentCommand.ENV_EXITED, worker_id, ex)
         )

ml-agents/mlagents/trainers/torch/model_serialization.py

@@ -153,7 +153,7 @@ def export_policy_model(self, output_filepath: str) -> None:
         :param output_filepath: file path to output the model (without file suffix)
         """
         onnx_output_path = f"{output_filepath}.onnx"
-        logger.info(f"Converting to {onnx_output_path}")
+        logger.debug(f"Converting to {onnx_output_path}")
 
         with exporting_to_onnx():
             torch.onnx.export(

ml-agents/mlagents/trainers/trainer_controller.py

@@ -78,7 +78,7 @@ def _save_models(self):
 
         for brain_name in self.trainers.keys():
             self.trainers[brain_name].save_model()
-        self.logger.info("Saved Model")
+        self.logger.debug("Saved Model")
 
     @staticmethod
     def _create_output_path(output_path):