Restructure log location

Resolves #7 (closed)

mpsd-software-environment.py

@@ -32,17 +32,19 @@ for given system architecture and MPSD software stack version.\n
 The toolchains
 are built using the bash script spack_setup.sh, and the results are logged. """
 
-call_date_iso = datetime.datetime.now().replace(microsecond=0).isoformat()
+call_date_iso = (
+    datetime.datetime.now().replace(microsecond=0).isoformat().replace(":", "-")
+)
 config_vars = {
     #  kept inside the mpsd_release folder
-    "cmd_log_file": "install.log",
+    "cmd_log_file": "script_execution_summary.log",
     #  Placeholder installer log file name, placed at mpsd_microarch/logs
     "installer_log_template": Template(
-        "${mpsd_release}_${mpsd_microarch}_${date}_${action}.log"
+        "${mpsd_release}_${mpsd_microarch}_${date}_APEX_${action}.log"
     ),
     #  Placeholder build log file name, placed at mpsd_microarch/logs
     "build_log_template": Template(
-        "${mpsd_release}_${mpsd_microarch}_${date}_${toolchain}_${action}.log"
+        "${mpsd_release}_${mpsd_microarch}_${date}_BUILD_${toolchain}_${action}.log"
     ),
     "metadata_tag_open": "!<meta>",
     "metadata_tag_close": "</meta>!",
@@ -151,12 +153,34 @@ def read_metadata_from_logfile(logfile: Union[str, Path]) -> dict:
     }
 
 
-def set_up_logging(loglevel="warning", filename=None):
+def get_installer_log_file_path(mpsd_release: str, cmd: str, script_dir: str) -> str:
+    """Get installer log file path."""
+    # Get machine configs
+    os.environ.get("MPSD_OS", "UNKNOWN_OS")
+    mpsd_microarch = get_native_microarchitecture()
+    # parse logging first
+    # decide the log_file_name
+    installer_log_name, build_log_name = create_log_file_names(
+        mpsd_release=mpsd_release, mpsd_microarch=mpsd_microarch, action=cmd
+    )
+    log_folder = script_dir / mpsd_release / "logs"
+    # if the log_folder dosent exist, dont log this message if
+    #  the command is a info-only command
+    if cmd not in ["status", "available"]:
+        if not os.path.exists(log_folder):
+            os.makedirs(log_folder)
+        installer_log_file = log_folder / installer_log_name
+    else:
+        installer_log_file = None
+    return installer_log_file
+
+
+def set_up_logging(loglevel="warning", file_path=None):
     """Set up logging.
 
     This function sets up the logging configuration for the script.
     It configures the log level, log format, and log handlers
-    for both file and console output.
+    for both file and console(=shell) output.
 
 
     Parameters
@@ -166,41 +190,133 @@ def set_up_logging(loglevel="warning", filename=None):
          - warning (default): only print statements if something is unexpected
          - info (show more detailed progress)
          - debug (show very detailed output)
-    filename : str
+    file_path : str
          - filename to save logging messages into
 
     If loglevel is 'debug', save line numbers in log messages.
+
+    Returns
+    -------
+    None.
+
+    Logger instances are generally not passed around, but retrieved from the
+    logging module as shown below (they are singletons).
+
+    We provide two loggers:
+
+    1. log = logging.getLogger('')
+
+       This is the 'root' logger. It uses a RichHandler if rich is available for
+       output to the shell, otherwise plain text.
+
+       Typical use:
+
+       log.debug("...")
+       log.info("...")
+       log.warn("...")
+
+       Equivalent to
+
+       logging.debug("...")
+       logging.info("...")
+
+    2. print_log = logging.getlogger('print')
+
+       This uses the logging module to issue the message, but prints without
+       any further markup (i.e. no date, loglevel, line number, etc). Think
+       PRINT via the LOGging module.
+
+       We use this as a replacement for the print function (i.e. for messages
+       that should not be affected by logging levels, and which should always
+       be printed).
+
+       Typical and intended use:
+
+       print_log.info("Available toolchains are ...")
+
+       The major difference from the normal print command is that the output
+       will be send to the stdout (as for print) AND the file with name
+       filename, so that these messages appear in the log file together with
+       normal log output.
+
     """
+    # convert loglevel string into loglevel as number
     log_level_numeric = getattr(logging, loglevel.upper(), logging.WARNING)
-    assert log_level_numeric
     if not isinstance(log_level_numeric, int):
         raise ValueError("Invalid log level: %s" % loglevel)
 
-    handlers = []
-    if filename:
-        handlers.append(logging.FileHandler(filename))
+    # set up the main logger ("root" logger)
+    logger = logging.getLogger("")
+    # - "logger" logs everything
+    # - we use loglevel at handler level to write everything to file
+    # - and filter using  log_level_numeric (as the user provides) to
+    #   send logging messages to the console
+    logger.setLevel(0)
 
+    # the handler determines where the logs go: stdout/file
     if rich_available:
-        # set up logging as recommended for rich, see
         # https://rich.readthedocs.io/en/stable/logging.html
-        handlers.append(rich.logging.RichHandler())
+        shell_handler = rich.logging.RichHandler()
+        # rich handler provides metadata automatically:
         logging_format = "%(message)s"
-    else:  # rich not available, define our own output
+        # for shell output, only show time (not date and time)
+        shell_formatter = logging.Formatter(logging_format, datefmt="[%X]")
+    else:
+        shell_handler = logging.StreamHandler()
         # include line numbers in output if level is DEBUG
         linenumbers = " %(lineno)4d" if log_level_numeric == logging.DEBUG else ""
-        handlers.append(logging.StreamHandler())
         logging_format = "%(asctime)s %(levelname)7s" + linenumbers + "  |  %(message)s"
-
-    logging.basicConfig(
-        level=log_level_numeric,
-        format=logging_format,
-        datefmt="[%X]",
-        handlers=handlers,
-        force=True,
-    )
+        shell_formatter = logging.Formatter(logging_format)
+
+    # here we hook everything together
+    shell_handler.setFormatter(shell_formatter)
+    # use the log_level_numeric to decide how much logging is sent to shell
+    shell_handler.setLevel(log_level_numeric)
+
+    # Here we set the handlers of the RootLogger to be just the one we want.
+    # The reason is that the logging module will add a <StreamHandler <stderr>
+    # (NOTSET)> handler if logging.info/logging.debug/... is used before we
+    # come across this line. And we do not want that additional handler.
+    logger.handlers = [shell_handler]
+
+    # if filename provided, write log messages to that file, too.
+    if file_path:
+        file_handler = logging.FileHandler(file_path)
+        # if we have a file, we write all information in there.
+        # We could change the level, for example restrict to only DEBUG and above with
+        # file_handler.setLevel(logging.DEBUG)
+        file_logging_format = "%(asctime)s %(levelname)7s %(lineno)4d  |  %(message)s"
+        file_formatter = logging.Formatter(file_logging_format, datefmt="[%X]")
+        file_handler.setFormatter(file_formatter)
+        logger.addHandler(file_handler)
+
+    #
+    # new logger for printing
+    #
+    print_log = logging.getLogger("print")
+    print_log.setLevel(logging.INFO)
+    print_log.propagate = False
+    # create formatter 'empty' formatter
+    formatter = logging.Formatter("%(message)s")
+
+    # create, format and add handler for shell output
+    ch = logging.StreamHandler()
+    ch.setFormatter(formatter)
+    print_log.addHandler(ch)
+
+    # if filename provided, write output of print_log to that file, too
+    if file_path:
+        # create, format and add file handler
+        fh = logging.FileHandler(file_path)
+        fh.setFormatter(formatter)
+        print_log.addHandler(fh)
+
+    #
+    # short message
+    #
     logging.debug(
-        f"Logging has been setup, loglevel={loglevel.upper()}"
-        + f"{filename=} {rich_available=}"
+        f"Logging has been setup, loglevel={loglevel.upper()} "
+        + f"{file_path=} {rich_available=}"
     )
 
 
@@ -651,6 +767,8 @@ def install_environment(
             "No toolchains requested. Available toolchains for release "
             f"{mpsd_release} are: \n {available_toolchains}"
         )
+        print_log = logging.getLogger("print")
+        print_log.info(f"{available_toolchains=}")
         return
 
     for toolchain in toolchains:
@@ -672,7 +790,7 @@ def install_environment(
                 mpsd_release, mpsd_microarch, "install", toolchain=toolchain
             )
             build_log_folder = release_base_dir / "logs"
-            build_log_file = build_log_folder / build_log_file_name
+            build_log_path = build_log_folder / build_log_file_name
             # if logs folder dosent exist, create it
             if not os.path.exists(build_log_folder):
                 os.makedirs(build_log_folder)
@@ -683,19 +801,19 @@ def install_environment(
             setup_log_cmd(
                 mpsd_release,
                 script_dir,
-                msg=f"installing {toolchain} and logging at {build_log_file}",
+                msg=f"installing {toolchain} and logging at {build_log_path}",
             )
             setup_log_cmd(
                 mpsd_release,
                 script_dir,
                 msg=(
-                    f"CMD: bash {spack_setup_script} {' '.join(install_flags)}"
-                    "{toolchain}"
+                    f"CMD: bash {spack_setup_script} {' '.join(install_flags)} "
+                    f"{toolchain}"
                 ),
             )
             run(
                 f"bash {spack_setup_script} {' '.join(install_flags)} {toolchain} 2>&1 "
-                f"| tee -a {build_log_file} ",
+                f"| tee -a {build_log_path} ",
                 shell=True,
                 check=True,
             )
@@ -796,28 +914,13 @@ def main():
     # Carry out the action
     args = parser.parse_args()
 
-    # Get machine configs
-    os.environ.get("MPSD_OS", "UNKNOWN_OS")
-    mpsd_microarch = get_native_microarchitecture()
     # target dir is the place where this script exists. the
     script_dir = Path(os.path.dirname(os.path.realpath(__file__)))
-    mpsd_release = args.release
-    # parse logging first
-    # decide the log_file_name
-    installer_log_name, build_log_name = create_log_file_names(
-        mpsd_release=mpsd_release, mpsd_microarch=mpsd_microarch, action=args.action
-    )
-    log_folder = script_dir / mpsd_release / mpsd_microarch / "logs"
-    # if the log_folder dosent exist, dont log this message if
-    #  the command is a info-only command
-    if not os.path.exists(log_folder):
-        if args.action not in ["status", "available"]:
-            os.makedirs(log_folder)
-            installer_log_file = log_folder / installer_log_name
-        else:
-            installer_log_file = None
 
-    set_up_logging(args.loglevel, installer_log_file)
+    set_up_logging(
+        args.loglevel,
+        get_installer_log_file_path(args.release, args.action, script_dir),
+    )
 
     # Check the command and run related function
     if args.action == "remove":