Comment 2 for bug 1989009

Reviewed: https://review.opendev.org/c/starlingx/root/+/858434
Committed: https://opendev.org/starlingx/root/commit/818830b25e338d7f8b6ac4408c67fd6fc7df29a7
Submitter: "Zuul (22348)"
Branch: master

commit 818830b25e338d7f8b6ac4408c67fd6fc7df29a7
Author: M. Vefa Bicakci <email address hidden>
Date: Fri Sep 16 19:05:42 2022 +0000

    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 <email address hidden>