Add colorized output to log.info and log.step_info for bracket prefixes

src/popper/log.py

@@ -36,17 +36,17 @@ class PopperFormatter(logging.Formatter):
 
     log_format = {
         "DEBUG": f"{BOLD_CYAN}%(levelname)s: %(msg)s {RESET}",
-        "STEP_INFO": "%(msg)s",
-        "INFO": "%(msg)s",
+        "STEP_INFO": f"{BOLD_CYAN}%(pretag)s{RESET} %(msg)s",
+        "INFO": f"{BOLD_CYAN}%(pretag)s{RESET} %(msg)s",
         "WARNING": f"{BOLD_YELLOW}%(levelname)s: %(msg)s{RESET}",
         "ERROR": f"{BOLD_RED}%(levelname)s: %(msg)s{RESET}",
         "CRITICAL": f"{BOLD_RED}%(levelname)s: %(msg)s{RESET}",
     }
 
     log_format_no_colors = {
         "DEBUG": "%(levelname)s: %(msg)s ",
-        "STEP_INFO": "%(msg)s",
-        "INFO": "%(msg)s",
+        "STEP_INFO": "%(pretag)s %(msg)s",
+        "INFO": "%(pretag)s %(msg)s",
         "WARNING": "%(levelname)s: %(msg)s",
         "ERROR": "%(levelname)s: %(msg)s",
         "CRITICAL": "%(levelname)s: %(msg)s",
@@ -55,6 +55,7 @@ class PopperFormatter(logging.Formatter):
     def __init__(self, colors=True):
         super(PopperFormatter, self).__init__(fmt="%(levelname)s: %(msg)s")
         self.log_fmt = self.log_format if colors else self.log_format_no_colors
+        self.colors = colors
 
     def format(self, record):
         """
@@ -72,7 +73,11 @@ def format(self, record):
             self._fmt = fmt
         else:
             self._style._fmt = fmt
-        result = f"{msg_prefix}{logging.Formatter.format(self, record)}"
+
+        if self.colors:
+            result = f"{self.BOLD_CYAN}{msg_prefix}{self.RESET}{logging.Formatter.format(self, record)}"
+        else:
+            result = f"{msg_prefix}{logging.Formatter.format(self, record)}"
         return result
 
 
@@ -183,6 +188,8 @@ def filter(self, record):
           bool : True/False according to values of pass levels and level number
                 of the record.
         """
+        if not hasattr(record, "pretag"):
+            record.pretag = ""
         if self.reject:
             return record.levelno not in self.passlevels
         else:

src/popper/runner.py

@@ -126,13 +126,12 @@ def _clone_repos(self, wf):
                 continue
 
             if not infoed:
-                log.info("[popper] Cloning step repositories")
+                log.info("Cloning step repositories", extra={"pretag": "[popper]"})
                 infoed = True
 
             if f"{user}/{repo}" in cloned:
                 continue
-
-            log.info(f"[popper] - {url}/{user}/{repo}@{version}")
+            log.info(f"- {url}/{user}/{repo}@{version}", extra={"pretag": "[popper]"})
             scm.clone(url, user, repo, repo_dir, version)
             cloned.add(f"{user}/{repo}")
 

src/popper/runner_host.py

@@ -40,7 +40,7 @@ def run(self, step):
             raise AttributeError("Expecting 'runs' attribute in step.")
         cmd = step.runs + tuple(step.args)
 
-        log.info(f"[{step.id}] {cmd}")
+        log.info(f"{cmd}", extra={"pretag": f"[{step.id}]"})
 
         if self._config.dry_run:
             return 0
@@ -146,7 +146,7 @@ def run(self, step):
         if not container and not self._config.reuse:
             container = self._create_container(cid, step)
 
-        log.info(f"[{step.id}] docker start")
+        log.info("docker start", extra={"pretag": f"[{step.id}]"})
 
         if self._config.dry_run:
             return 0
@@ -177,7 +177,10 @@ def _create_container(self, cid, step):
         build, _, img, tag, build_ctx_path = self._get_build_info(step)
 
         if build:
-            log.info(f"[{step.id}] docker build {img}:{tag} {build_ctx_path}")
+            log.info(
+                f"docker build {img}:{tag} {build_ctx_path}",
+                extra={"pretag": f"[{step.id}]"},
+            )
             if not self._config.dry_run:
                 streamer = self._d.api.build(
                     decode=True, path=build_ctx_path, tag=f"{img}:{tag}", rm=True,
@@ -191,7 +194,7 @@ def _create_container(self, cid, step):
                             log.step_info(line.strip())
 
         elif not self._config.skip_pull and not step.skip_pull:
-            log.info(f"[{step.id}] docker pull {img}:{tag}")
+            log.info(f"docker pull {img}:{tag}", extra={"pretag": f"[{step.id}]"})
             if not self._config.dry_run:
                 self._d.images.pull(repository=f"{img}:{tag}")
 
@@ -209,13 +212,13 @@ def _create_container(self, cid, step):
 
         log.debug(f"Container args: {container_args}")
 
-        msg = f"[{step.id}] docker create name={cid}"
+        msg = f"docker create name={cid}"
         msg += f' image={container_args["image"]}'
         if container_args["entrypoint"]:
             msg += f' entrypoint={container_args["entrypoint"]}'
         if container_args["command"]:
             msg += f' command={container_args["command"]}'
-        log.info(msg)
+        log.info(msg, extra={"pretag": f"[{step.id}]"})
 
         container = self._d.containers.create(**container_args)
 
@@ -272,7 +275,7 @@ def run(self, step):
         if not container and not self._config.reuse:
             container = self._create_container(cid, step)
 
-        log.info(f"[{step.id}] podman start")
+        log.info("podman start", extra={"pretag": f"[{step.id}]"})
 
         if self._config.dry_run:
             return 0
@@ -309,7 +312,10 @@ def _create_container(self, cid, step):
         build, _, img, tag, build_ctx_path = self._get_build_info(step)
 
         if build:
-            log.info(f"[{step.id}] podman build {img}:{tag} {build_ctx_path}")
+            log.info(
+                f"podman build {img}:{tag} {build_ctx_path}",
+                extra={"pretag": f"[{step.id}]"},
+            )
             if not self._config.dry_run:
                 cmd = [
                     "podman",
@@ -322,7 +328,7 @@ def _create_container(self, cid, step):
                 ]
                 HostRunner._exec_cmd(cmd)
         elif not self._config.skip_pull and not step.skip_pull:
-            log.info(f"[{step.id}] podman pull {img}:{tag}")
+            log.info(f"podman pull {img}:{tag}", extra={"pretag": f"[{step.id}]"})
             if not self._config.dry_run:
                 cmd = ["podman", "pull", f"{img}:{tag}"]
                 HostRunner._exec_cmd(cmd, logging=False)
@@ -517,11 +523,16 @@ def _create_container(self, step, cid):
             build_ctx_path = None
 
         if build:
-            log.info(f"[{step.id}] singularity build {cid} {build_ctx_path}")
+            log.info(
+                f"singularity build {cid} {build_ctx_path}",
+                extra={"pretag": f"[{step.id}]"},
+            )
             if not self._config.dry_run:
                 self._build_from_recipe(build_ctx_path, self._singularity_cache, cid)
         elif not self._config.skip_pull and not step.skip_pull:
-            log.info(f"[{step.id}] singularity pull {cid} {image}")
+            log.info(
+                f"singularity pull {cid} {image}", extra={"pretag": f"[{step.id}]"}
+            )
             if not self._config.dry_run:
                 self._s.pull(image=image, name=cid, pull_folder=self._singularity_cache)
 
@@ -537,15 +548,15 @@ def _singularity_start(self, step, cid):
         ecode = None
 
         if runs:
-            info = f"[{step.id}] singularity exec {cid} {runs}"
+            info = f"singularity exec {cid} {runs}"
             commands = runs
             start_fn = self._s.execute
         else:
-            info = f"[{step.id}] singularity run {cid} {args}"
+            info = f"singularity run {cid} {args}"
             commands = args
             start_fn = self._s.run
 
-        log.info(info)
+        log.info(info, extra={"pretag": f"[{step.id}]"})
 
         if self._config.dry_run:
             return 0

src/popper/runner_kubernetes.py

@@ -61,8 +61,8 @@ def run(self, step):
 
         image = f"{img}:{tag}"
 
-        m = f"[{step.id}] kubernetes run {self._namespace}.{self._pod_name}"
-        log.info(m)
+        m = f"kubernetes run {self._namespace}.{self._pod_name}"
+        log.info(m, extra={"pretag": f"[{step.id}]"})
 
         if self._config.dry_run:
             return 0

src/popper/runner_slurm.py

@@ -167,24 +167,36 @@ def run(self, step):
 
         if build:
             recipefile = self._get_recipe_file(build_ctx_path, cid)
-            log.info(f"[{step.id}] srun singularity build {self._container}")
+            log.info(
+                f"srun singularity build {self._container}",
+                extra={"pretag": f"[{step.id}]"},
+            )
             self._exec_srun(
-                ["singularity", "build", "--fakeroot", self._container, recipefile,],
+                [
+                    "singularity",
+                    "build",
+                    "--fakeroot",
+                    self._container,
+                    recipefile,
+                ],
                 step,
                 cwd=os.path.dirname(recipefile),
             )
         else:
-            log.info(f"[{step.id}] srun singularity pull {self._container}")
+            log.info(
+                f"srun singularity pull {self._container}",
+                extra={"pretag": f"[{step.id}]"},
+            )
             self._exec_srun(["singularity", "pull", self._container, img], step)
 
         cmd = self._create_cmd(step, cid)
         self._spawned_containers.add(cid)
 
         if self._config.resman_opts.get(step.id, {}).get("mpi", True):
-            log.info(f'[{step.id}] sbatch {" ".join(cmd)}')
+            log.info(f"sbatch {" ".join(cmd)}", extra={"pretag": f"[{step.id}]"})
             ecode = self._exec_mpi(cmd, step)
         else:
-            log.info(f'[{step.id}] srun {" ".join(cmd)}')
+            log.info(f"srun {" ".join(cmd)}", extra={"pretag": f"[{step.id}]"})
             ecode = self._exec_srun(cmd, step, logging=True)
 
         self._spawned_containers.remove(cid)