Fix package-installs-v2 output

The current output for package-installs-v2 is inscrutable [1]

The problem starts with process_output() which is not capturing
stderr.  This means that any stderr output is dislocated from any
stdout output around it.  This is *really* confusing as you get a
bunch of seemingly meaningless stderr output from any calls before you
see any stdout (e.g. in [1] you can see random yum error output that
should have been with the yum call)).  The simplest thing to do is to
redirect stderr to stdout which keeps everything in sync.

This causes a slight problem, however, because pkg-map outputs both
status information and errors on stderr.  To work around this but
maintain compatibility, we add a "--prefix" argument that prepends
mapped packages from pkg-map with a value we can match on.  The
existing status/debug output from pkg-map is low-value; modify the
call so that it will be traced only at higher debug levels (e.g. -x
-x).

The current loop is also calling pkg-map for every package in every
element (this is why in [1] the same message is repeated over and
over).  This is unnecessary; it only needs to pkg-map once for each
element, giving the package list as the arguments.  Create package
lists by element and pass those to pkg-map.

As a cleanup, there is no point in printing e.output if the
process_output fails for the install because we are already tracing
it; i.e. the output, even for failures, is already in the logs.
Printing it again just duplicates the output.

[2] is an extract showing what I feel is a much more understandable
log output for a fairly complex install.

[1] http://paste.openstack.org/show/595118/
[2] http://paste.openstack.org/show/595303/

Change-Id: Ia74602a5d2db032a476481caec0e45dab013d54f

diskimage_builder/elements/package-installs/bin/package-installs-v2

@@ -18,14 +18,18 @@ from __future__ import print_function
 
 import argparse
 import json
+import os
 import subprocess
 import sys
 
+from collections import defaultdict
+
 
 # run a command, return output
 #  if follow is set, output will be echoed to stdout
 def process_output(cmdline, follow=False):
     proc = subprocess.Popen(cmdline, stdout=subprocess.PIPE,
+                            stderr=subprocess.STDOUT,
                             universal_newlines=True)
     if follow:
         print("Running command: %s" % cmdline)
@@ -48,6 +52,8 @@ def process_output(cmdline, follow=False):
 
 
 def main():
+    dbg_level = int(os.getenv('DIB_DEBUG_TRACE', '0'))
+
     parser = argparse.ArgumentParser(
         description="Install or uninstall packages for a specific phase based"
                     " on package-installs files.")
@@ -75,13 +81,31 @@ def main():
         print("Nothing to %s" % install)
         sys.exit(0)
 
+    # sort the list by element, this way we only do one pkg-map call
+    # per element
+    by_element = defaultdict(list)
     for (pkg, element) in install_packages:
-        print("%sing %s from %s" % (install, pkg, element))
+        by_element[element].append(pkg)
-        pkg_map_args = ['pkg-map', '--missing-ok', '--element', element, pkg]
+
+    for element, packages in by_element.items():
+        print("Map %s for %s: %s" % (install, element, ', '.join(packages)))
+
+        # Only trace pkg-map for higher levels of debugging.  Note
+        # that pkg-map debug output comes out on stderr, which is
+        # captured into the output by process_output.  We filter by
+        # "prefix" so we don't think the debug lines are packages!
+        pkg_map_args = ['pkg-map', '--prefix', '-',
+                        '--missing-ok', '--element', element]
+        if dbg_level > 1:
+            pkg_map_args.append('--debug')
+        pkg_map_args.extend(packages)
 
         try:
-            map_output = process_output(pkg_map_args)
+            follow = True if dbg_level > 1 else False
-            pkgs.extend(map_output.strip().split('\n'))
+            map_output = process_output(pkg_map_args, follow=follow)
+            map_output = map_output.strip().split('\n')
+            map_output = [m[1:] for m in map_output if m.startswith('-')]
+            pkgs.extend(map_output)
         except subprocess.CalledProcessError as e:
             if e.returncode == 1:
                 if args.noop:
@@ -105,7 +129,7 @@ def main():
         try:
             process_output(install_args, follow=True)
         except subprocess.CalledProcessError as e:
-            print("install failed with error %s" % e.output)
+            print("install-packages failed with returncode %d" % e.returncode)
             sys.exit(1)
 
 

diskimage_builder/elements/pkg-map/bin/pkg-map

@@ -18,13 +18,10 @@ import argparse
 import json
 import logging
 import os
-import pprint
 import sys
 
 
-def eprint(msg):
+log = logging.getLogger()
-    sys.stderr.write(msg)
-    sys.stderr.write("\n")
 
 
 def os_family(distro):
@@ -60,47 +57,61 @@ def main():
                         help='Do not consider missing mappings an error.'
                              ' Causes packages where no mapping is set to be'
                              ' printed.')
+    # This tool has traditionally output status and debug messages on
+    # stderr.  The problem is if a caller has stderr > stdout then
+    # actual output gets messed in with the logs.  This allows callers
+    # to disambiguate actual output by specifying a unique prefix.
+    parser.add_argument('--prefix', default='',
+                        help='Output mapped packages with this prefix')
     parser.add_argument('--debug', dest='debug', action="store_true",
                         help="Enable debugging output")
 
     args, extra = parser.parse_known_args()
 
-    if args.debug:
+    # Logs have traditionally gone to stderr with this tool.  Maintain
-        logging.basicConfig(level=logging.DEBUG)
+    # compatability
+    level = logging.DEBUG if args.debug else logging.INFO
+    logging.basicConfig(stream=sys.stderr, level=level)
 
     if not args.element and not args.pkg_map:
-        eprint('Please specify an --element argument.')
+        log.error('Please specify an --element argument.')
         sys.exit(1)
 
     if args.element and args.pkg_map:
-        eprint('Specify either --element or --pkg-map')
+        log.error('Specify either --element or --pkg-map')
         sys.exit(1)
 
     if not args.distro:
-        eprint('Please specify a --distro argument or set DISTRO_NAME.')
+        log.error('Please specify a --distro argument or set DISTRO_NAME.')
         sys.exit(1)
 
     if args.pkg_map:
+        # specifying the pkg-map by hand is just for manual testing
+        element = "<%s>" % args.pkg_map
         map_file = args.pkg_map
     else:
-        map_file = '/usr/share/pkg-map/%s' % args.element
+        element = args.element
+        map_file = '/usr/share/pkg-map/%s' % element
+
+    log.info("Mapping for %s : %s" % (element, ' '.join(extra)))
 
-    logging.debug("Map file is %s" % map_file)
     if not os.path.exists(map_file):
-        if os.environ.get('DIB_DEBUG_TRACE', '0') != '0':
-            eprint('Map file for %s element does not exist.' % args.element)
         if args.missing_ok:
+            log.info("No package map for %s, done" % element)
             for name in extra:
-                print(name)
+                print('%s%s' % (args.prefix, name))
             sys.exit(0)
-        sys.exit(2)
+        else:
+            log.error('Required pkg-map for %s element does not exist.'
+                      % args.element)
+            sys.exit(2)
 
     with open(map_file) as fd:
         try:
             package_names = json.loads(fd.read())
-            logging.debug(pprint.pformat(package_names))
+            # log.debug(pprint.pformat(package_names))
         except ValueError:
-            eprint('Unable to parse %s' % map_file)
+            log.error('Unable to parse %s' % map_file)
             raise
 
     # Parse mapping data in this form using release/distro/family/default
@@ -158,21 +169,31 @@ def main():
         except KeyError:
             pass
 
+    # log.debug(pprint.pformat(name_map))
+
     for name in extra:
         pkg_name = name_map.get(name)
         if pkg_name:
-            print(pkg_name)
+            log.debug("map %s -> %s" % (name, pkg_name))
+            print('%s%s' % (args.prefix, pkg_name))
         elif name in name_map:
+            log.debug("map %s -> <skip>" % (name))
             continue
         else:
-            err_msg = 'Missing package name for distro/element: %s/%s'
-            eprint(err_msg % (args.distro, args.element))
             if args.missing_ok:
-                print(name)
+                log.debug("pass -> %s" % (name))
+                print('%s%s' % (args.prefix, name))
             else:
+                log.error("%s has no valid mapping for package %s" %
+                          (element, name))
                 sys.exit(1)
 
     sys.exit(0)
 
 if __name__ == '__main__':
     main()
+
+# Tell emacs to use python-mode
+# Local variables:
+# mode: python
+# End: