Refactored logs and added log-to-json feature (removed the old log-to-file feature), added logging test utils. (#403)

* refactored logging, and logging to file feature.

* cleaned up old tests

* Update tests/test_logging/test_logging.py

Co-authored-by: Hugues Devimeux <[email protected]>
Co-authored-by: Pg Biel <[email protected]>
Co-authored-by: Leo Torres <[email protected]>

Author: 4 people

docs/source/changelog.rst

@@ -89,6 +89,8 @@ Of interest to developers
 #. Added autogenerated documentation with sphinx and autodoc/autosummary [WIP]
 #. Made manim internally use relative imports
 #. Since the introduction of the :code:`TexTemplate` class, the files :code:`tex_template.tex` and :code:`ctex_template.tex` have been removed
+#. Added logging tests tools.
+#. Added ability to save logs in json
 #. Move to Poetry.
 
 Other Changes

manim/__main__.py

@@ -14,6 +14,7 @@
 from .scene.scene import Scene
 from .utils.sounds import play_error_sound, play_finish_sound
 from .utils.file_ops import open_file as open_media_file
+from . import constants
 
 
 def open_file_if_needed(file_writer):

manim/config/config.py

@@ -18,9 +18,11 @@
 from .. import constants
 from .config_utils import _run_config, _init_dirs, _from_command_line
 
-from .logger import logger
+from .logger import set_rich_logger, set_file_logger, logger
 from ..utils.tex import TexTemplate, TexTemplateFromFile
 
+__all__ = ["file_writer_config", "config", "camera_config", "tempconfig"]
+
 
 config = None
 
@@ -150,3 +152,14 @@ def _parse_config(config_parser, args):
         _init_dirs(file_writer_config)
 config = _parse_config(config_parser, args)
 camera_config = config
+
+# Set the different loggers
+set_rich_logger(config_parser["logger"], file_writer_config["verbosity"])
+if file_writer_config["log_to_file"]:
+    # IMPORTANT note about file name : The log file name will be the scene_name get from the args (contained in file_writer_config). So it can differ from the real name of the scene.
+    log_file_path = os.path.join(
+        file_writer_config["log_dir"],
+        "".join(file_writer_config["scene_names"]) + ".log",
+    )
+    set_file_logger(log_file_path)
+    logger.info("Log file wil be saved in %(logpath)s", {"logpath": log_file_path})

manim/config/config_utils.py

@@ -69,9 +69,15 @@ def _parse_file_writer_config(config_parser, args):
             default.getboolean(boolean_opt) if attr is None else attr
         )
     # for str_opt in ['media_dir', 'video_dir', 'tex_dir', 'text_dir']:
-    for str_opt in ["media_dir", "log_dir"]:
+    for str_opt in ["media_dir"]:
         attr = getattr(args, str_opt)
         fw_config[str_opt] = os.path.relpath(default[str_opt]) if attr is None else attr
+    attr = getattr(args, "log_dir")
+    fw_config["log_dir"] = (
+        os.path.join(fw_config["media_dir"], default["log_dir"])
+        if attr is None
+        else attr
+    )
     dir_names = {
         "video_dir": "videos",
         "images_dir": "images",

manim/config/default.cfg

@@ -75,8 +75,8 @@ upto_animation_number = -1
 # as well as Tex and texts.
 media_dir = ./media
 
-# --log_dir
-log_dir = %(media_dir)s/logs
+# --log_dir (by default "/logs", that will be put inside the media dir)
+log_dir = logs
 
 # If the -t (--transparent) flag is used, these will be replaced with the
 # values specified in the [TRANSPARENT] section later in this file.

manim/config/logger.py

@@ -18,24 +18,41 @@
 from rich.theme import Theme
 from rich import print as printf
 from rich import errors, color
+import json
+import copy
 
-from .config_utils import _run_config
 
+class JSONFormatter(logging.Formatter):
+    """Subclass of `:class:`logging.Formatter`, to build our own format of the logs (JSON)."""
 
-def parse_theme(fp):
-    config_parser.read(fp)
-    theme = dict(config_parser["logger"])
-    # replaces `_` by `.` as rich understands it
+    def format(self, record):
+        record_c = copy.deepcopy(record)
+        if record_c.args:
+            for arg in record_c.args:
+                record_c.args[arg] = "<>"
+        return json.dumps(
+            {
+                "levelname": record_c.levelname,
+                "module": record_c.module,
+                "message": super().format(record_c),
+            }
+        )
+
+
+def _parse_theme(config_logger):
     theme = dict(
-        zip([key.replace("_", ".") for key in theme.keys()], list(theme.values()))
+        zip(
+            [key.replace("_", ".") for key in config_logger.keys()],
+            list(config_logger.values()),
+        )
     )
 
     theme["log.width"] = None if theme["log.width"] == "-1" else int(theme["log.width"])
 
     theme["log.height"] = (
         None if theme["log.height"] == "-1" else int(theme["log.height"])
     )
-    theme["log.timestamps"] = config_parser["logger"].getboolean("log.timestamps")
+    theme["log.timestamps"] = False
     try:
         customTheme = Theme(
             {
@@ -49,51 +66,54 @@ def parse_theme(fp):
         printf(
             "[logging.level.error]It seems your colour configuration couldn't be parsed. Loading the default color configuration...[/logging.level.error]"
         )
-    return customTheme, theme
-
-
-config_items = _run_config()
-config_parser, successfully_read_files = config_items[1], config_items[-1]
-try:
-    customTheme, themedict = parse_theme(successfully_read_files)
-    console = Console(
-        theme=customTheme,
-        record=True,
-        height=themedict["log.height"],
-        width=themedict["log.width"],
-    )
-except KeyError:
-    console = Console(record=True)
-    printf(
-        "[logging.level.warning]No cfg file found, creating one in "
-        + successfully_read_files[0]
-        + " [/logging.level.warning]"
+    return customTheme
+
+
+def set_rich_logger(config_logger, verbosity):
+    """Will set the RichHandler of the logger.
+
+    Parameter
+    ----------
+    config_logger :class:
+        Config object of the logger.
+    """
+    theme = _parse_theme(config_logger)
+    global console
+    console = Console(theme=theme)
+    # These keywords Are Highlighted specially.
+    RichHandler.KEYWORDS = [
+        "Played",
+        "animations",
+        "scene",
+        "Reading",
+        "Writing",
+        "script",
+        "arguments",
+        "Invalid",
+        "Aborting",
+        "module",
+        "File",
+        "Rendering",
+        "Rendered",
+    ]
+    rich_handler = RichHandler(
+        console=console, show_time=config_logger.getboolean("log_timestamps")
     )
+    global logger
+    rich_handler.setLevel(verbosity)
+    logger.addHandler(rich_handler)
+
+
+def set_file_logger(log_file_path):
+    file_handler = logging.FileHandler(log_file_path, mode="w")
+    file_handler.setFormatter(JSONFormatter())
+    global logger
+    logger.addHandler(file_handler)
+
 
-# These keywords Are Highlighted specially.
-RichHandler.KEYWORDS = [
-    "Played",
-    "animations",
-    "scene",
-    "Reading",
-    "Writing",
-    "script",
-    "arguments",
-    "Invalid",
-    "Aborting",
-    "module",
-    "File",
-    "Rendering",
-    "Rendered",
-]
-logging.basicConfig(
-    level="NOTSET",
-    format="%(message)s",
-    datefmt="[%X]",
-    handlers=[RichHandler(console=console, show_time=themedict["log.timestamps"])],
-)
-
-logger = logging.getLogger("rich")
+logger = logging.getLogger("manim")
+# The console is set to None as it will be changed by set_rich_logger.
+console = None
 
 # TODO : This is only temporary to keep the terminal output clean when working with ImageMobject and matplotlib plots
 logging.getLogger("PIL").setLevel(logging.INFO)

manim/scene/scene.py

@@ -816,7 +816,8 @@ def wrapper(self, *args, **kwargs):
                 self.play_hashes_list.append(hash_play)
                 if self.file_writer.is_already_cached(hash_play):
                     logger.info(
-                        f"Animation {self.num_plays} : Using cached data (hash : {hash_play})"
+                        f"Animation {self.num_plays} : Using cached data (hash : %(hash_play)s)",
+                        {"hash_play": hash_play},
                     )
                     file_writer_config["skip_animations"] = True
             else:

manim/scene/scene_file_writer.py

@@ -454,7 +454,8 @@ def close_movie_pipe(self):
             self.partial_movie_file_path,
         )
         logger.info(
-            f"Animation {self.scene.num_plays} : Partial movie file written in {self.partial_movie_file_path}"
+            f"Animation {self.scene.num_plays} : Partial movie file written in %(path)s",
+            {"path": {self.partial_movie_file_path}},
         )
 
     def is_already_cached(self, hash_invocation):
@@ -616,21 +617,12 @@ def flush_cache_directory(self):
         for f in cached_partial_movies:
             os.remove(f)
         logger.info(
-            f"Cache flushed. {len(cached_partial_movies)} file(s) deleted in {self.partial_movie_directory}."
+            f"Cache flushed. {len(cached_partial_movies)} file(s) deleted in %(par_dir)s.",
+            {"par_dir": self.partial_movie_directory},
         )
 
     def print_file_ready_message(self, file_path):
         """
         Prints the "File Ready" message to STDOUT.
         """
-        logger.info("\nFile ready at {}\n".format(file_path))
-
-        if file_writer_config["log_to_file"]:
-            self.write_log()
-
-    def write_log(self):
-        log_file_path = os.path.join(
-            file_writer_config["log_dir"], f"{self.get_default_scene_name()}.log"
-        )
-        console.save_text(log_file_path)
-        logger.info("Log written to {}\n".format(log_file_path))
+        logger.info("\nFile ready at %(file_path)s\n", {"file_path": file_path})

manim/utils/hashing.py

@@ -244,7 +244,7 @@ def get_hash_from_play_call(
         for json_val in [camera_json, animations_list_json, current_mobjects_list_json]
     ]
     t_end = perf_counter()
-    logger.debug("Hashing done in {:.5f} s.".format(t_end - t_start))
+    logger.debug("Hashing done in %(time)s s.", {"time": str(t_end - t_start)[:8]})
     # This will reset ALREADY_PROCESSED_ID as all the hashing processus is finished.
     ALREADY_PROCESSED_ID = {}
     return "{}_{}_{}".format(hash_camera, hash_animations, hash_current_mobjects)
@@ -291,7 +291,7 @@ def get_hash_from_wait_call(
         # This will reset ALREADY_PROCESSED_ID as all the hashing processus is finished.
         ALREADY_PROCESSED_ID = {}
         t_end = perf_counter()
-        logger.debug("Hashing done in {:.5f} s.".format(t_end - t_start))
+        logger.debug("Hashing done in %(time)s s.", {"time": str(t_end - t_start)[:8]})
         return "{}_{}{}_{}".format(
             hash_camera,
             str(wait_time).replace(".", "-"),
@@ -300,7 +300,7 @@ def get_hash_from_wait_call(
         )
     ALREADY_PROCESSED_ID = {}
     t_end = perf_counter()
-    logger.debug("Hashing done in {:.5f} s.".format(t_end - t_start))
+    logger.debug("Hashing done in %(time)s s.", {"time": str(t_end - t_start)[:8]})
     return "{}_{}_{}".format(
         hash_camera, str(wait_time).replace(".", "-"), hash_current_mobjects
     )

tests/control_data/logs_data/BasicSceneLoggingTest.txt

@@ -0,0 +1,6 @@
+{"levelname": "INFO", "module": "config", "message": "Log file wil be saved in <>"}
+{"levelname": "DEBUG", "module": "hashing", "message": "Hashing ..."}
+{"levelname": "DEBUG", "module": "hashing", "message": "Hashing done in <> s."}
+{"levelname": "INFO", "module": "scene_file_writer", "message": "Animation 0 : Partial movie file written in <>"}
+{"levelname": "INFO", "module": "scene_file_writer", "message": "\nFile ready at <>\n"}
+{"levelname": "INFO", "module": "scene", "message": "Rendered SquareToCircle\nPlayed 1 animations"}