diff --git a/src/popper/log.py b/src/popper/log.py old mode 100644 new mode 100755 index ce8b7b31e..4db5b5e50 --- a/src/popper/log.py +++ b/src/popper/log.py @@ -36,8 +36,8 @@ 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}", @@ -45,8 +45,8 @@ class PopperFormatter(logging.Formatter): 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: diff --git a/src/popper/runner.py b/src/popper/runner.py old mode 100644 new mode 100755 index 51ffd7ad0..31a26a67d --- a/src/popper/runner.py +++ b/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}") diff --git a/src/popper/runner_host.py b/src/popper/runner_host.py old mode 100644 new mode 100755 index adf95a68e..27d477189 --- a/src/popper/runner_host.py +++ b/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 diff --git a/src/popper/runner_kubernetes.py b/src/popper/runner_kubernetes.py index d6054bef4..5fe0482ac 100644 --- a/src/popper/runner_kubernetes.py +++ b/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 diff --git a/src/popper/runner_slurm.py b/src/popper/runner_slurm.py old mode 100644 new mode 100755 index 2bbc16bb9..21c933af0 --- a/src/popper/runner_slurm.py +++ b/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)