Fix how we set logging levels #3703

chriselion · 2020-03-27T19:06:02Z

Proposed change(s)

Haven't been able to reproduce this locally, but there are several reports that some log lines are not appearing. So far, the ones noted are this:

ml-agents/ml-agents-envs/mlagents_envs/environment.py

Lines 130 to 133 in 8c61299

    
           logger.info( 
        
               f"Listening on port {self.port}. " 
        
               f"Start training by pressing the Play button in the Unity Editor." 
        
           )

with logged created here:

ml-agents/ml-agents-envs/mlagents_envs/environment.py

Line 50 in 8c61299

logger = logging.getLogger("mlagents_envs")

and the summary report

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

Lines 201 to 214 in 6fa4190

    
           logger.info( 
        
               "{}: {}: Step: {}. " 
        
               "Time Elapsed: {:0.3f} s " 
        
               "Mean " 
        
               "Reward: {:0.3f}" 
        
               ". Std of Reward: {:0.3f}. {}".format( 
        
                   self.run_id, 
        
                   self.brain_name, 
        
                   step, 
        
                   time.time() - self.training_start_time, 
        
                   stats_summary.mean, 
        
                   stats_summary.std, 
        
                   is_training, 
        
               )

configured here

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

Line 23 in 6fa4190

logger = logging.getLogger("mlagents.trainers")

The speculation is that some other import is calling logging.basicConfig before we get to it, so we never set the log level.

This centralizes all the logging creation through logging_util (no more logging.getLogger()) and sets the log level explicitly for all loggers.

Useful links (Github issues, JIRA tickets, ML-Agents forum threads etc.)

https://jira.unity3d.com/browse/MLA-737
https://jira.unity3d.com/browse/MLA-608
https://forum.unity.com/threads/prompt-doesnt-display-start-training-by-pressing-the-play-button-in-the-unity-editor.852481/

Types of change(s)

Checklist

Added tests that prove my fix is effective or that my feature works
Updated the changelog (if applicable)
Updated the documentation (if applicable)
Updated the migration guide (if applicable)

Other comments

chriselion · 2020-03-27T20:52:23Z

ml-agents-envs/mlagents_envs/logging_util.py

@@ -0,0 +1,46 @@
+import logging  # noqa I251


This is moved from mlagents_envs/logging_util.py and heavily modified.

chriselion · 2020-03-27T20:52:47Z

ml-agents-envs/mlagents_envs/logging_util.py

@@ -0,0 +1,46 @@
+import logging  # noqa I251
+
+CRITICAL = logging.CRITICAL


Imported here so that calling code doesn't need to import logging

chriselion · 2020-03-27T20:55:11Z

gym-unity/gym_unity/envs/__init__.py

-logging.basicConfig(level=logging.INFO)
-logger = logging.getLogger("gym_unity")
-
+logger = get_logger(__name__)


Recommended logging practice is to use __name__ for the logger name: https://docs.python.org/3.7/library/logging.html#logger-objects

chriselion · 2020-03-27T20:57:56Z

ml-agents-envs/mlagents_envs/logging_util.py

+    # first, it doesn't have any effect.
+    logging.basicConfig(level=_log_level, format=LOG_FORMAT, datefmt=DATE_FORMAT)
+
+    for logger in _loggers:


In theory, if we use __name__ everywhere, we should be able to do something like

logging.getLogger("mlagents").setLevel(log_level) logging.getLogger("mlagents_envs").setLevel(log_level) logging.getLogger("gym_unity").setLevel(log_level)

here, and let the logger name hierarchy handle things, but I went for the explicit approach instead.

chriselion · 2020-03-27T20:58:56Z

setup.cfg

@@ -20,3 +20,4 @@ ignore =
    I200,

 banned-modules = tensorflow = use mlagents.tf_utils instead (it handles tf2 compat).
+                 logging = use mlagents_envs.logging_util instead


This prevents logging from being imported, so that all new code will use logging_util .get_logger instead.

ervteng · 2020-03-27T21:30:09Z

gym-unity/gym_unity/envs/__init__.py

-logger = logging.getLogger("gym_unity")
-
+logger = get_logger(__name__)
+set_log_level(INFO)


Very nit: it seems kind of weird to import INFO as a global variable - could we import logging_util and do logging_util.INFO as we do in the learn.py?

Sure, sounds good.

vincentpierre · 2020-03-30T17:38:10Z

ml-agents/mlagents/trainers/learn.py

@@ -30,7 +29,9 @@
 from mlagents_envs.side_channel.engine_configuration_channel import EngineConfig
 from mlagents_envs.exception import UnityEnvironmentException
 from mlagents_envs.timers import hierarchical_timer, get_timer_tree
-from mlagents.logging_util import create_logger
+from mlagents_envs import logging_util


Do we need to import everything ?

I received the opposite feedback from @ervteng on Friday, see #3703 (comment)

I think this is preferable when we want to use the logging levels; it's clearer in the code to see logging_util.INFO instead of INFO.

Another alternative is to use import logging and disable the "banned module" error here.

vincentpierre · 2020-03-30T17:39:26Z

ml-agents/mlagents/trainers/learn.py

@@ -30,7 +29,9 @@
 from mlagents_envs.side_channel.engine_configuration_channel import EngineConfig
 from mlagents_envs.exception import UnityEnvironmentException
 from mlagents_envs.timers import hierarchical_timer, get_timer_tree
-from mlagents.logging_util import create_logger
+from mlagents_envs import logging_util


Suggested change

from mlagents_envs import logging_util

from mlagents_envs.logging_util import get_logger, set_log_level, INFO, DEBUG

* cleanup logging * comments and cleanup * pylint, gym

* [bug-fix] Increase height of wall in CrawlerStatic (#3650) * [bug-fix] Improve performance for PPO with continuous actions (#3662) * Corrected a typo in a name of a function (#3670) OnEpsiodeBegin was corrected to OnEpisodeBegin in Migrating.md document * Add Academy.AutomaticSteppingEnabled to migration (#3666) * Fix editor port in Dockerfile (#3674) * Hotfix memory leak on Python (#3664) * Hotfix memory leak on Python * Fixing * Fixing a bug in the heuristic policy. A decision should not be requested when the agent is done * [bug-fix] Make Python able to deal with 0-step episodes (#3671) * adding some comments Co-authored-by: Ervin T <ervin@unity3d.com> * Remove vis_encode_type from list of required (#3677) * Update changelog (#3678) * Shorten timeout duration for environment close (#3679) The timeout duration for closing an environment was set to the same duration as the timeout when waiting for a response from the still-running environment. This led to long waits for the error response when communication version wasn't matching. This change forces a timeout duration of 0 when handling errors. * Bumping the versions * handle multiple dones in a single step (#3700) * handle multiple dones in a single step * [tests] Make end-to-end tests more stable (#3697) * [bug-fix] Fix entropy computation for GaussianDistribution (#3684) * Fix how we set logging levels (#3703) * cleanup logging * comments and cleanup * pylint, gym * [skip-ci] Update changelog for logging fix. (#3707) * [skip ci] Update README * [skip ci] Fixed a typo Co-authored-by: Ervin T <ervin@unity3d.com> Co-authored-by: Adam Streck <adam.streck@gmail.com> Co-authored-by: Chris Elion <chris.elion@unity3d.com> Co-authored-by: Jonathan Harper <jharper+moar@unity3d.com>

* Bumping version on the release (#3615) * Update examples project to 2018.4.18f1 (#3618) From 2018.4.14f1. An internal package dependency was updated as a side effect. * Remove dead components from the examples scenes (#3619) (#3624) * Improve warnings and exception if using unsupported combo * add meta file * fix unit test * enforce onnx conversion (expect tf2 CI to fail) (#3600) * Update error message * Updated the release branch docs (#3621) * Updated the release branch docs * Edited the README * make sure top-level timer is closed before writing * Remove space from Product Name for examples In #2588 it was suggested that the space in the Product Name for our example environments causes confusion when using a default build because of the need to escape the space in the build filename. This change removes the space from the Product Name in the project's player settings. * [bug-fix] Increase 3dballhard and GAIL default steps (#3636) * Updating the NN models (#3632) * Updating the NN models * Update gridworld * [skip ci] Update BallHard * Update hallway * Hotfixes for Release 0.15.1 (#3698) * [bug-fix] Increase height of wall in CrawlerStatic (#3650) * [bug-fix] Improve performance for PPO with continuous actions (#3662) * Corrected a typo in a name of a function (#3670) OnEpsiodeBegin was corrected to OnEpisodeBegin in Migrating.md document * Add Academy.AutomaticSteppingEnabled to migration (#3666) * Fix editor port in Dockerfile (#3674) * Hotfix memory leak on Python (#3664) * Hotfix memory leak on Python * Fixing * Fixing a bug in the heuristic policy. A decision should not be requested when the agent is done * [bug-fix] Make Python able to deal with 0-step episodes (#3671) * adding some comments Co-authored-by: Ervin T <ervin@unity3d.com> * Remove vis_encode_type from list of required (#3677) * Update changelog (#3678) * Shorten timeout duration for environment close (#3679) The timeout duration for closing an environment was set to the same duration as the timeout when waiting for a response from the still-running environment. This led to long waits for the error response when communication version wasn't matching. This change forces a timeout duration of 0 when handling errors. * Bumping the versions * handle multiple dones in a single step (#3700) * handle multiple dones in a single step * [tests] Make end-to-end tests more stable (#3697) * [bug-fix] Fix entropy computation for GaussianDistribution (#3684) * Fix how we set logging levels (#3703) * cleanup logging * comments and cleanup * pylint, gym * [skip-ci] Update changelog for logging fix. (#3707) * [skip ci] Update README * [skip ci] Fixed a typo Co-authored-by: Ervin T <ervin@unity3d.com> Co-authored-by: Adam Streck <adam.streck@gmail.com> Co-authored-by: Chris Elion <chris.elion@unity3d.com> Co-authored-by: Jonathan Harper <jharper+moar@unity3d.com> * fix changelog * keep master gridworld Co-authored-by: Vincent-Pierre BERGES <vincentpierre@unity3d.com> Co-authored-by: Jonathan Harper <jharper+moar@unity3d.com> Co-authored-by: Ervin T <ervin@unity3d.com> Co-authored-by: Adam Streck <adam.streck@gmail.com>

Chris Elion added 2 commits March 27, 2020 11:02

cleanup logging

3948bee

comments and cleanup

3989e06

chriselion changed the title ~~Develop mla 737 logging~~ Fix how we set logging levels Mar 27, 2020

chriselion commented Mar 27, 2020

View reviewed changes

chriselion requested review from ervteng, vincentpierre and anupam-142857 March 27, 2020 20:59

ervteng reviewed Mar 27, 2020

View reviewed changes

pylint, gym

b62160c

vincentpierre approved these changes Mar 30, 2020

View reviewed changes

chriselion merged commit ebeb034 into master Mar 30, 2020

delete-merged-branch bot deleted the develop-MLA-737-logging branch March 30, 2020 18:33

chriselion mentioned this pull request Mar 30, 2020

Update changelog for logging fix. #3707

Merged

10 tasks

vincentpierre pushed a commit that referenced this pull request Mar 30, 2020

Fix how we set logging levels (#3703)

d18d555

* cleanup logging * comments and cleanup * pylint, gym

surfnerd mentioned this pull request Apr 1, 2020

UnityTimeOutException: The Unity environment took too long to respond. #3683

Closed

github-actions bot locked as resolved and limited conversation to collaborators May 15, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Fix how we set logging levels #3703

Fix how we set logging levels #3703

Uh oh!

chriselion commented Mar 27, 2020 •

edited

Loading

Uh oh!

chriselion Mar 27, 2020

Uh oh!

chriselion Mar 27, 2020

Uh oh!

chriselion Mar 27, 2020

Uh oh!

chriselion Mar 27, 2020

Uh oh!

chriselion Mar 27, 2020

Uh oh!

ervteng Mar 27, 2020

Uh oh!

chriselion Mar 27, 2020

Uh oh!

vincentpierre Mar 30, 2020

Uh oh!

chriselion Mar 30, 2020

Uh oh!

vincentpierre Mar 30, 2020

Uh oh!

Uh oh!

	logger.info(
	f"Listening on port {self.port}. "
	f"Start training by pressing the Play button in the Unity Editor."
	)

	logger.info(
	"{}: {}: Step: {}. "
	"Time Elapsed: {:0.3f} s "
	"Mean "
	"Reward: {:0.3f}"
	". Std of Reward: {:0.3f}. {}".format(
	self.run_id,
	self.brain_name,
	step,
	time.time() - self.training_start_time,
	stats_summary.mean,
	stats_summary.std,
	is_training,
	)

		@@ -0,0 +1,46 @@
		import logging # noqa I251

		CRITICAL = logging.CRITICAL

	from mlagents_envs import logging_util
	from mlagents_envs.logging_util import get_logger, set_log_level, INFO, DEBUG

Fix how we set logging levels #3703

Fix how we set logging levels #3703

Uh oh!

Conversation

chriselion commented Mar 27, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Proposed change(s)

Useful links (Github issues, JIRA tickets, ML-Agents forum threads etc.)

Types of change(s)

Checklist

Other comments

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

chriselion commented Mar 27, 2020 •

edited

Loading