Restructure log location

Resolves #7 (closed)

mpsd-software-environment.py

@@ -151,12 +151,34 @@ def read_metadata_from_logfile(logfile: Union[str, Path]) -> dict:
     }
 
 
+def get_installer_log_file(mpsd_release: str, cmd: str, script_dir: str) -> str:
+    """Get installer log file name."""
+    # 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", filename=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
@@ -170,36 +192,128 @@ def set_up_logging(loglevel="warning", filename=None):
          - 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"
+        shell_formatter = logging.Formatter(logging_format)
 
-    logging.basicConfig(
-        level=log_level_numeric,
-        format=logging_format,
-        datefmt="[%X]",
-        handlers=handlers,
-        force=True,
-    )
+    # 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 filename:
+        file_handler = logging.FileHandler(filename)
+        # 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 filename:
+        # create, format and add file handler
+        fh = logging.FileHandler(filename)
+        fh.setFormatter(formatter)
+        print_log.addHandler(fh)
+
+    #
+    # short message
+    #
     logging.debug(
-        f"Logging has been setup, loglevel={loglevel.upper()}"
+        f"Logging has been setup, loglevel={loglevel.upper()} "
         + f"{filename=} {rich_available=}"
     )
 
@@ -651,6 +765,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:
@@ -689,8 +805,8 @@ def install_environment(
                 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(
@@ -796,28 +912,12 @@ 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(args.release, args.action, script_dir)
+    )
 
     # Check the command and run related function
     if args.action == "remove":