From 365b5b9600b41d92182ce7b232828020d1f7d9d7 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Hugo=20H=C3=B6rnquist?= <hugo@lysator.liu.se>
Date: Mon, 24 Jan 2022 22:25:02 +0100
Subject: Subprocess output now sent to log.

---
 TODO    |  2 --
 main.py | 58 +++++++++++++++++++++++++++++++++++++++++++++++-----------
 2 files changed, 47 insertions(+), 13 deletions(-)

diff --git a/TODO b/TODO
index a4d68da..34abe53 100644
--- a/TODO
+++ b/TODO
@@ -1,5 +1,3 @@
 * Use Target
 	Possibly respect the TARGET attribute from auracle, and don't flag
 	those packages as dependencies
-* Log subprocess stdout and stderr
-	Currently only return codes are logged
diff --git a/main.py b/main.py
index 386c53f..94e55ca 100755
--- a/main.py
+++ b/main.py
@@ -43,7 +43,7 @@ logging:
   formatters:
     detailed:
       class: logging.Formatter
-      format: '[%(asctime)s] %(name)-15s %(levelname)-8s %(message)s'
+      format: '[%(asctime)s] %(levelname)-8s %(message)s'
       datefmt: '%Y-%m-%dT%H:%M:%S'
   handlers:
     console:
@@ -83,12 +83,47 @@ def get_conf(key, default=None):
 logging.config.dictConfig(get_conf('logging'))
 logger = logging.getLogger(__name__)
 
-def log_cmd(cmd):
-    if cmd.returncode == 0:
-        logger.info('%s finished without errors', cmd.args)
+
+def subprocess_with_log(*args, capture_output=False, **kv_args):
+    """
+    Run a process as by subprocess.run, but also log output which isn't captured by user.
+
+    Note that it is currently unspecified what happens if user tries
+    to capture stderr.
+    """
+    if capture_output:
+        kv_args['stdout'] = subprocess.PIPE
+
+    if not capture_output and not kv_args.get('stdout'):
+        kv_args['stdout'] = subprocess.PIPE
+        kv_args['stderr'] = subprocess.STDOUT
+        get_port = lambda process: process.stdout
+    else:
+        kv_args['stderr'] = subprocess.PIPE
+        get_port = lambda process: process.stderr
+
+    process = subprocess.Popen(*args, **kv_args,)
+    logger.info('pid = %i, exec(%s)', process.pid, process.args)
+
+    if kv_args.get('text'):
+        sentinel = ''
     else:
-        logger.warning('%s exited with status code %s', cmd.args, cmd.returncode)
+        sentinel = b''
+
+    with get_port(process) as pipe:
+        for line in iter(pipe.readline, sentinel):
+            logger.debug('%i: %s', process.pid, line)
 
+    process.wait()
+
+    if capture_output:
+        process.stdout = process.stdout.read()
+
+    if process.returncode == 0:
+        logger.info('%i exit success', process.pid)
+    else:
+        logger.warning('%i exit failure = %s', process.pid, process.returncode)
+    return process
 
 auracle_args = ['--color=never']
 pacman_args  = ['--noconfirm', '--asdeps', '--noprogressbar', '--needed']
@@ -107,8 +142,7 @@ def gather_packages(pkgs):
     """
     repo_pkgs = []
     aur_pkgs = []
-    cmd = subprocess.run(['auracle', *auracle_args, 'buildorder', *pkgs], capture_output=True, text=True)
-    log_cmd(cmd)
+    cmd = subprocess_with_log(['auracle', *auracle_args, 'buildorder', *pkgs], capture_output=True, text=True)
 
     for line in cmd.stdout.split('\n'):
         if not line: continue
@@ -140,6 +174,9 @@ def gather_packages(pkgs):
 
 
 def main():
+
+    logger.info('Starting run')
+
     with open(get_conf('package-list')) as f:
         data = yaml.safe_load(f)
 
@@ -169,12 +206,11 @@ def main():
 
     if repo_pkgs:
         logger.info('Installing from the repos: %s', repo_pkgs)
-        log_cmd(subprocess.run(['sudo', 'pacman', *pacman_args, '-S', *repo_pkgs]))
+        subprocess_with_log(['sudo', 'pacman', *pacman_args, '-S', *repo_pkgs])
 
     for package in aur_pkgs:
-        cmd = subprocess.run(['auracle', *auracle_args, '--chdir', cachedir, 'clone', package],
+        cmd = subprocess_with_log(['auracle', *auracle_args, '--chdir', cachedir, 'clone', package],
                 capture_output=True, text=True)
-        log_cmd(cmd)
         m = re.match('[^:]*: (.*)', cmd.stdout)
         if not m:
             logger.error('Auracle clone had unexpected output [%s], skipping package [%s]',
@@ -184,7 +220,7 @@ def main():
         env = { 'PKGDEST': pkgdest,
                 'PATH': ':'.join(path),
                 }
-        log_cmd(subprocess.run(['makepkg', *makepkg_args, '--install', *pacman_args], env=env, cwd=cwd))
+        subprocess_with_log(['makepkg', *makepkg_args, '--install', *pacman_args], env=env, cwd=cwd)
 
 if __name__ == '__main__':
     if os.getuid() == 0:
-- 
cgit v1.2.3