Output: use logging, remove garbage output by default

Fixes #489.

Introduces a --verbose flag if you want to see all the noise that
was previously printed by default.

Signed-off-by: James O'Beirne <james.obeirne@pm.me>
Signed-off-by: Florian Maurer <f.maurer@outlook.de>

Author: jamesob

podman_compose.py

@@ -14,6 +14,7 @@
 import hashlib
 import itertools
 import json
+import logging
 import os
 import random
 import re
@@ -78,16 +79,7 @@ def try_float(i, fallback=None):
     return fallback
 
 
-def log(*msgs, sep=" ", end="\n"):
-    try:
-        current_task = asyncio.current_task()
-    except RuntimeError:
-        current_task = None
-    line = (sep.join([str(msg) for msg in msgs])) + end
-    if current_task and not current_task.get_name().startswith("Task"):
-        line = f"[{current_task.get_name()}] " + line
-    sys.stderr.write(line)
-    sys.stderr.flush()
+log = logging.getLogger(__name__)
 
 
 dir_re = re.compile(r"^[~/\.]")
@@ -387,7 +379,7 @@ async def assert_volume(compose, mount_dict):
     proj_name = compose.project_name
     vol_name = vol["name"]
     is_ext = vol.get("external", None)
-    log(f"podman volume inspect {vol_name} || podman volume create {vol_name}")
+    log.debug(f"podman volume inspect {vol_name} || podman volume create {vol_name}")
     # TODO: might move to using "volume list"
     # podman volume list --format '{{.Name}}\t{{.MountPoint}}' \
     #     -f 'label=io.podman.compose.project=HERE'
@@ -563,7 +555,7 @@ def get_secret_args(compose, cnt, secret):
         volume_ref = ["--volume", f"{source_file}:{dest_file}:ro,rprivate,rbind"]
         if uid or gid or mode:
             sec = target if target else secret_name
-            log(
+            log.warn(
                 f'WARNING: Service {cnt["_service"]} uses secret "{sec}" with uid, gid, or mode.'
                 + " These fields are not supported by this implementation of the Compose file"
             )
@@ -594,7 +586,7 @@ def get_secret_args(compose, cnt, secret):
         if target and target != secret_name:
             raise ValueError(err_str.format(target, secret_name))
         if target:
-            log(
+            log.warn(
                 'WARNING: Service "{}" uses target: "{}" for secret: "{}".'.format(
                     cnt["_service"], target, secret_name
                 )
@@ -778,7 +770,7 @@ def get_net_args(compose, cnt):
         elif net.startswith("bridge"):
             is_bridge = True
         else:
-            print(f"unknown network_mode [{net}]")
+            log.fatal(f"unknown network_mode [{net}]")
             sys.exit(1)
     else:
         is_bridge = True
@@ -1154,7 +1146,7 @@ async def output(self, podman_args, cmd="", cmd_args=None):
             cmd_args = cmd_args or []
             xargs = self.compose.get_podman_args(cmd) if cmd else []
             cmd_ls = [self.podman_path, *podman_args, cmd] + xargs + cmd_args
-            log(cmd_ls)
+            log.info(str(cmd_ls))
             p = await asyncio.subprocess.create_subprocess_exec(
                 *cmd_ls, stdout=asyncio.subprocess.PIPE, stderr=asyncio.subprocess.PIPE
             )
@@ -1174,7 +1166,7 @@ def exec(
         cmd_args = list(map(str, cmd_args or []))
         xargs = self.compose.get_podman_args(cmd) if cmd else []
         cmd_ls = [self.podman_path, *podman_args, cmd] + xargs + cmd_args
-        log(" ".join([str(i) for i in cmd_ls]))
+        log.info(" ".join([str(i) for i in cmd_ls]))
         os.execlp(self.podman_path, *cmd_ls)
 
     async def run(
@@ -1191,7 +1183,7 @@ async def run(
             cmd_args = list(map(str, cmd_args or []))
             xargs = self.compose.get_podman_args(cmd) if cmd else []
             cmd_ls = [self.podman_path, *podman_args, cmd] + xargs + cmd_args
-            log(" ".join([str(i) for i in cmd_ls]))
+            log.info(" ".join([str(i) for i in cmd_ls]))
             if self.dry_run:
                 return None
 
@@ -1225,16 +1217,16 @@ async def format_out(stdout):
             try:
                 exit_code = await p.wait()
             except asyncio.CancelledError:
-                log("Sending termination signal")
+                log.info("Sending termination signal")
                 p.terminate()
                 try:
                     exit_code = await wait_with_timeout(p.wait(), 10)
                 except TimeoutError:
-                    log("container did not shut down after 10 seconds, killing")
+                    log.warning("container did not shut down after 10 seconds, killing")
                     p.kill()
                     exit_code = await p.wait()
 
-            log(f"exit code: {exit_code}")
+            log.info(f"exit code: {exit_code}")
             return exit_code
 
     async def volume_ls(self, proj=None):
@@ -1482,7 +1474,7 @@ def assert_services(self, services):
         missing = given - self.all_services
         if missing:
             missing_csv = ",".join(missing)
-            log(f"missing services [{missing_csv}]")
+            log.warn(f"missing services [{missing_csv}]")
             sys.exit(1)
 
     def get_podman_args(self, cmd):
@@ -1496,7 +1488,7 @@ def get_podman_args(self, cmd):
         return xargs
 
     async def run(self):
-        log("podman-compose version: " + __version__)
+        log.info("podman-compose version: " + __version__)
         args = self._parse_args()
         podman_path = args.podman_path
         if podman_path != "podman":
@@ -1505,7 +1497,7 @@ async def run(self):
             else:
                 # this also works if podman hasn't been installed now
                 if args.dry_run is False:
-                    log(f"Binary {podman_path} has not been found.")
+                    log.fatal(f"Binary {podman_path} has not been found.")
                     sys.exit(1)
         self.podman = Podman(self, podman_path, args.dry_run, asyncio.Semaphore(args.parallel))
 
@@ -1519,9 +1511,9 @@ async def run(self):
             except subprocess.CalledProcessError:
                 self.podman_version = None
             if not self.podman_version:
-                log("it seems that you do not have `podman` installed")
+                log.fatal("it seems that you do not have `podman` installed")
                 sys.exit(1)
-            log("using podman version: " + self.podman_version)
+            log.info("using podman version: " + self.podman_version)
         cmd_name = args.command
         compose_required = cmd_name != "version" and (
             cmd_name != "systemd" or args.action != "create-unit"
@@ -1549,15 +1541,15 @@ def _parse_compose_file(self):
             args.file = list(filter(os.path.exists, default_ls))
         files = args.file
         if not files:
-            log(
+            log.fatal(
                 "no compose.yaml, docker-compose.yml or container-compose.yml file found, "
                 "pass files with -f"
             )
             sys.exit(-1)
         ex = map(os.path.exists, files)
         missing = [fn0 for ex0, fn0 in zip(ex, files) if not ex0]
         if missing:
-            log("missing files: ", missing)
+            log.fatal("missing files: %s", missing)
             sys.exit(1)
         # make absolute
         relative_files = files
@@ -1635,7 +1627,7 @@ def _parse_compose_file(self):
         compose["_dirname"] = dirname
         # debug mode
         if len(files) > 1:
-            log(" ** merged:\n", json.dumps(compose, indent=2))
+            log.debug(" ** merged:\n%s", json.dumps(compose, indent=2))
         # ver = compose.get('version', None)
 
         if not project_name:
@@ -1656,7 +1648,7 @@ def _parse_compose_file(self):
         services = compose.get("services", None)
         if services is None:
             services = {}
-            log("WARNING: No services defined")
+            log.warn("WARNING: No services defined")
         # include services with no profile defined or the selected profiles
         services = self._resolve_profiles(services, set(args.profile))
 
@@ -1689,7 +1681,7 @@ def _parse_compose_file(self):
         unused_nets = given_nets - allnets - set(["default"])
         if len(unused_nets):
             unused_nets_str = ",".join(unused_nets)
-            log(f"WARNING: unused networks: {unused_nets_str}")
+            log.warn(f"WARNING: unused networks: {unused_nets_str}")
         if len(missing_nets):
             missing_nets_str = ",".join(missing_nets)
             raise RuntimeError(f"missing networks: {missing_nets_str}")
@@ -1800,6 +1792,8 @@ def _parse_args(self):
         if not self.global_args.command or self.global_args.command == "help":
             parser.print_help()
             sys.exit(-1)
+
+        logging.basicConfig(level=('DEBUG' if self.global_args.verbose else 'WARN'))
         return self.global_args
 
     @staticmethod
@@ -1887,6 +1881,11 @@ def _init_global_parser(parser):
         parser.add_argument(
             "--parallel", type=int, default=os.environ.get("COMPOSE_PARALLEL_LIMIT", sys.maxsize)
         )
+        parser.add_argument(
+            "--verbose",
+            help="Print debugging output",
+            action="store_true",
+        )
 
 
 podman_compose = PodmanCompose()
@@ -1982,15 +1981,15 @@ async def compose_systemd(compose, args):
         proj_name = compose.project_name
         fn = os.path.expanduser(f"~/{stacks_dir}/{proj_name}.env")
         os.makedirs(os.path.dirname(fn), exist_ok=True)
-        print(f"writing [{fn}]: ...")
+        log.debug(f"writing [{fn}]: ...")
         with open(fn, "w", encoding="utf-8") as f:
             for k, v in compose.environ.items():
                 if k.startswith("COMPOSE_") or k.startswith("PODMAN_"):
                     f.write(f"{k}={v}\n")
-        print(f"writing [{fn}]: done.")
-        print("\n\ncreating the pod without starting it: ...\n\n")
+        log.debug(f"writing [{fn}]: done.")
+        log.info("\n\ncreating the pod without starting it: ...\n\n")
         process = await asyncio.subprocess.create_subprocess_exec(script, ["up", "--no-start"])
-        print("\nfinal exit code is ", process)
+        log.info("\nfinal exit code is ", process)
         username = getpass.getuser()
         print(
             f"""
@@ -2037,18 +2036,18 @@ async def compose_systemd(compose, args):
 WantedBy=default.target
 """
         if os.access(os.path.dirname(fn), os.W_OK):
-            print(f"writing [{fn}]: ...")
+            log.debug(f"writing [{fn}]: ...")
             with open(fn, "w", encoding="utf-8") as f:
                 f.write(out)
-            print(f"writing [{fn}]: done.")
+            log.debug(f"writing [{fn}]: done.")
             print(
                 """
 while in your project type `podman-compose systemd -a register`
 """
             )
         else:
             print(out)
-            log(f"Could not write to [{fn}], use 'sudo'")
+            log.warn(f"Could not write to [{fn}], use 'sudo'")
 
 
 @cmd_run(podman_compose, "pull", "pull stack images")
@@ -2188,7 +2187,7 @@ def get_excluded(compose, args):
         for service in args.services:
             excluded -= compose.services[service]["_deps"]
             excluded.discard(service)
-    log("** excluding: ", excluded)
+    log.debug("** excluding: %s", excluded)
     return excluded
 
 
@@ -2221,18 +2220,18 @@ async def compose_up(compose: PodmanCompose, args):
     )
     diff_hashes = [i for i in hashes if i and i != compose.yaml_hash]
     if args.force_recreate or len(diff_hashes):
-        log("recreating: ...")
+        log.info("recreating: ...")
         down_args = argparse.Namespace(**dict(args.__dict__, volumes=False))
         await compose.commands["down"](compose, down_args)
-        log("recreating: done\n\n")
+        log.info("recreating: done\n\n")
     # args.no_recreate disables check for changes (which is not implemented)
 
     podman_command = "run" if args.detach and not args.no_start else "create"
 
     await create_pods(compose, args)
     for cnt in compose.containers:
         if cnt["_service"] in excluded:
-            log("** skipping: ", cnt["name"])
+            log.debug("** skipping: %s", cnt["name"])
             continue
         podman_args = await container_to_args(compose, cnt, detached=args.detach)
         subproc = await compose.podman.run([], podman_command, podman_args)
@@ -2264,7 +2263,7 @@ async def compose_up(compose: PodmanCompose, args):
         space_suffix = " " * (max_service_length - len(cnt["_service"]) + 1)
         log_formatter = "{}[{}]{}|\x1b[0m".format(color, cnt["_service"], space_suffix)
         if cnt["_service"] in excluded:
-            log("** skipping: ", cnt["name"])
+            log.debug("** skipping: %s", cnt["name"])
             continue
 
         tasks.add(
@@ -2368,7 +2367,7 @@ async def compose_down(compose, args):
             if cnt["_service"] not in excluded:
                 continue
             vol_names_to_keep.update(get_volume_names(compose, cnt))
-        log("keep", vol_names_to_keep)
+        log.debug("keep", vol_names_to_keep)
         for volume_name in await compose.podman.volume_ls():
             if volume_name in vol_names_to_keep:
                 continue
@@ -2643,7 +2642,7 @@ async def compose_unpause(compose, args):
 async def compose_kill(compose, args):
     # to ensure that the user did not execute the command by mistake
     if not args.services and not args.all:
-        print(
+        log.fatal(
             "Error: you must provide at least one service name or use (--all) to kill all services"
         )
         sys.exit()