Debian/stx: utils: Minor run_shell_cmd fix-ups

This commit fixes various minor issues in utils.py Python module's
run_shell_cmd function:

- Fix "local variable 'process' referenced before assignment" exception
  that can occur while handling exceptions raised by subprocess.Popen().
  This appears to only occur when a forked/child process cannot execute
  a program, which is a programming error, which in turn is a minor
  issue.

  Before this commit, attempting to run a non-existent program with, for
  example: 'run_shell_command("/bin/abc", ...)' would result in the
  exception "local variable 'process' referenced before assignment"
  while handling the exception "[Errno 2] No such file or directory:
  '/bin/abc'".

  With this commit, only the latter exception is reported, but in the
  following form, as part of a single/non-nested exception:

    [ Failed to execute command: "['/bin/abc']" Exception: "[Errno 2] \
      No such file or directory: '/bin/abc'" ]

- Avoid making Python print two tracebacks when handling exceptions
  raised by subprocess.Popen(). Logging a one-line description of the
  exception encountered by subprocess.Popen() (via "{e}", where "e" is
  an Exception object) is sufficient on its own to debug the encountered
  issue. (Please see above for an example.)

- Always log standard error of the command. While most of the messages
  logged to the standard error are debugging-oriented or point at minor
  issues, ignoring standard error still causes us to miss non-critical
  warning messages. In addition, change the log level for standard error
  output from "error" to "debug" to avoid panicking build system users
  due to the non-critical messages that will appear, such as the
  following:

  dpkg-architecture: warning: cannot determine CC system type, falling \
    back to default (native compilation)
  dpkg-source --before-build .
  dpkg-buildpackage: warning: building a source package without \
    cleaning up as you asked; it might contain undesired files
  dpkg-source -b .
  dpkg-genbuildinfo --build=source
  dpkg-genchanges --build=source >../mlnx-ofed-kernel_....changes
  dpkg-genchanges: info: not including original source code in upload

- In the logs, prefix the command's standard output with "stdout: " and
  its standard error with "stderr: ". This allows distinguishing between
  the command's messages emitted via standard output and standard error.

- Note that adding the "stdout: " prefix to each line of each command's
  standard output increases the log file's size by about 190 KiB,
  according to the following results from a fresh build with
  'build-pkgs -b std,rt -c -a':

    $ grep -e '2022-09-1[67] .*stdout: ' builder.log | wc -l
    24391 # num_lines
    $ echo $(( 24391 * 8 )) # i.e., num_lines * strlen("stdout: ")
    195128 # bytes

  Logging each command's standard error (along with prefixing each line
  with "stderr: ") adds about 1.87 MiB of output to the build logs,
  which corresponds to an increase of approximately 21 percent:

    $ grep -e '2022-09-1[67] .*stderr: ' builder.log | wc -c
    1963024
    $ grep -e '2022-09-1[67] ' builder.log | wc -c
    11164207
    $ echo 'scale=2; print 1963024.0/(11164207-1963024) * 100,"%\n";' \
        | bc
    21.00%

  Despite the increase in the log file size, logging the standard error
  uncovers some issues, mostly relating to the debian/changelog file
  formatting used by StarlingX developers, which are admittedly minor.
  Examples include:

  ... stderr: dpkg-genchanges: warning: debian/changelog(l...): \
    badly formatted trailer line
  ... stderr: dpkg-genchanges: warning: debian/changelog(l...): \
    found end of file where expected more change data or trailer

- Log the return code of the command if it fails. This provides
  additional information regarding why a command failed, in case the
  command's output is not sufficient to determine the reason.

- Prefer to log the command as a list/tuple if it is provided with that
  type, for easier correlation with the code and for consistency with
  the rest of the logging in the function.

- Improve logging and reduce the duplication involved in log message
  construction.

Verification
- 'build-pkgs -b rt,std -c -a' runs without issues with this patch, but
  emits additional output due to logging the standard error streams of
  executed commands.

Closes-Bug: 1989009
Closes-Bug: 1990177
Change-Id: I6b3c4dc70fb1404280ea15e8dcc573c83792f9b1
Signed-off-by: M. Vefa Bicakci <vefa.bicakci@windriver.com>

build-tools/stx/utils.py

@@ -129,34 +129,38 @@ def limited_walk(dir, max_depth=1):
 def run_shell_cmd(cmd, logger):
     if type(cmd) is str:
         shell = True
-        cmd_str = cmd
     elif type(cmd) in (tuple, list):
         shell = False
-        cmd_str = " ".join(cmd)
     else:
         raise Exception("Unrecognized 'cmd' type '%s'. Must be one of [str, list, tuple]." % (type(cmd)))
 
-    logger.info(f'[ Run - "{cmd_str}" ]')
+    logger.info(f'[ Run - "{cmd}" ]')
     try:
         process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
                                    universal_newlines=True, shell=shell)
-        # process.wait()
-        outs, errs = process.communicate()
-    except Exception:
-        process.kill()
-        outs, errs = process.communicate()
-        logger.error(f'[ Failed - "{cmd}" ]')
-        raise Exception(f'[ Failed - "{cmd}" ]')
+    except Exception as e:
+        msg = f'[ Failed to execute command: "{cmd}" Exception: "{e}" ]'
+        logger.error(msg)
+        # Suppress the original exception when raising our own exception.
+        # Syntax is acquired from: https://peps.python.org/pep-0409/#proposal
+        raise Exception(msg) from None
+
+    outs, errs = process.communicate()
 
     for log in outs.strip().split("\n"):
-        if log != "":
-            logger.debug(log.strip())
+        log = log.strip()
+        if log:
+            logger.debug("stdout: %s", log)
+
+    for log in errs.strip().split("\n"):
+        log = log.strip()
+        if log:
+            logger.debug("stderr: %s", log)
 
     if process.returncode != 0:
-        for log in errs.strip().split("\n"):
-            logger.error(log)
-        logger.error(f'[ Failed - "{cmd}" ]')
-        raise Exception(f'[ Failed - "{cmd}" ]')
+        msg = f'[ Command failed with a non-zero return code: "{cmd}" return code: {process.returncode} ]'
+        logger.error(msg)
+        raise Exception(msg)
 
     return outs.strip()