Add pkgpanda.util.MessageLogger

* MessageLogger provides a set of methods that improve logging when ran
  in the context of TeamCity.
  * The first type of method is `scope`, which allows the user to define
    a "block" where all other log messages created within the scope of the
    context managed method will be "in" that block and will be collapsed
    when viewing the log in TeamCity.
  * The second type of methods set specific log levels on the messages
    being logged, and in the case of error allows providing some error
    details.
  * When any of these methods are used in a context determined not to be
    TeamCity (determined by `is_running_uder_teamcity()`) the scope
    messages will not be printed, and the log level messages will be
    simplified removing the teamcity specific elements

Refactorings
============
1. create new package `teamcity-messages`. Rather than teamcity-messages
   only being added by tox, it is now a primary dependency of pkgpanda and
   dcos-image.
2. Add usage of new "scope" and "level" messages into pkgpanda and
   dcos-image for builds

Author: BenWhitehead

build_teamcity

@@ -2,9 +2,28 @@
 set -x
 set -o errexit -o pipefail
 
+function now { date +"%Y-%m-%dT%H:%M:%S.000" | tr -d '\n' ;}
+function _scope_msg() {
+    # Here we want to turn off `-x` that is present when running the bash script
+    # before we echo the message to teamcity, if we do not do this a "duplicate" echo will
+    # be printed to stderr and teamcity will error trying to parse the message because
+    # the format is invalid.
+    set +x
+    echo "##teamcity[block$1 timestamp='$(now)' name='$2']"
+    # Turn `-x` back on now that we're done sending the message to teamcity
+    set -x
+}
+function _scope_opened() {
+    _scope_msg "Opened" $1
+}
+function _scope_closed() {
+    _scope_msg "Closed" $1
+}
+
 # Fail quickly if docker daemon is not up
 systemctl status docker
 
+_scope_opened "cleanup"
 # cleanup from previous builds
 # *active.json and *.bootstrap.tar.xz must be cleaned up, otherwise
 # Teamcity starts picking up artifacts from previous builds.
@@ -20,7 +39,9 @@ rm -f CHANNEL_NAME
 rm -rf build/env
 rm -f dcos_generate_config*.sh
 rm -rf wheelhouse/
+_scope_closed "cleanup"
 
+_scope_opened "setup"
 # Force Python stdout/err to be unbuffered.
 export PYTHONUNBUFFERED="notemtpy"
 
@@ -42,14 +63,17 @@ CHANNEL_NAME=testing/$TAG
 echo tag: "$TAG"
 echo channel: "$CHANNEL_NAME"
 
+set +x
 echo "##teamcity[setParameter name='env.CHANNEL_NAME' value='$CHANNEL_NAME']"
 echo "##teamcity[setParameter name='env.TAG' value='$TAG']"
+set -x
 
 cp config/dcos-release.config.yaml dcos-release.config.yaml
 
 DIR="$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )"
 
 "$DIR"/prep_teamcity
+_scope_closed "setup"
 
 release create $TAG $TAG
 

gen/installer/aws.py

@@ -15,6 +15,7 @@
 import pkgpanda.util
 import release
 import release.storage
+from pkgpanda.util import logger
 
 aws_region_names = [
     {
@@ -481,8 +482,8 @@ def gen_templates(arguments):
         slave_cloud_config=variant_cloudconfig['slave'],
         slave_public_cloud_config=variant_cloudconfig['slave_public'])
 
-    print("Validating CloudFormation")
-    validate_cf(cloudformation)
+    with logger.scope("Validating CloudFormation"):
+        validate_cf(cloudformation)
 
     return gen.Bunch({
         'cloudformation': cloudformation,

gen/installer/bash.py

@@ -10,7 +10,7 @@
 import gen.installer.util as util
 import gen.template
 import pkgpanda.util
-
+from pkgpanda.util import logger
 
 file_template = """mkdir -p `dirname {filename}`
 cat <<'EOF' > "{filename}"
@@ -659,26 +659,28 @@ def do_create(tag, build_name, reproducible_artifact_path, commit, variant_argum
 
     Outputs the generated dcos_generate_config.sh as it's artifacts.
     """
-
     # TODO(cmaloney): Build installers in parallel.
     # Variants are sorted for stable ordering.
-    for variant, bootstrap_info in sorted(variant_arguments.items(), key=lambda kv: pkgpanda.util.variant_str(kv[0])):
-        print("Building installer for variant:", pkgpanda.util.variant_name(variant))
-        bootstrap_installer_name = '{}installer'.format(pkgpanda.util.variant_prefix(variant))
-        bootstrap_installer_id = all_bootstraps[bootstrap_installer_name]
-
-        installer_filename = make_installer_docker(variant, bootstrap_info['bootstrap_id'], bootstrap_installer_id)
-
-        yield {
-            'channel_path': 'dcos_generate_config.{}sh'.format(pkgpanda.util.variant_prefix(variant)),
-            'local_path': installer_filename
-        }
+    for variant, bootstrap_info in sorted(variant_arguments.items(),
+                                          key=lambda kv: pkgpanda.util.variant_str(kv[0])):
+        with logger.scope("Building installer for variant: ".format(pkgpanda.util.variant_name(variant))):
+            bootstrap_installer_name = '{}installer'.format(pkgpanda.util.variant_prefix(variant))
+            bootstrap_installer_id = all_bootstraps[bootstrap_installer_name]
+
+            installer_filename = make_installer_docker(variant, bootstrap_info['bootstrap_id'],
+                                                       bootstrap_installer_id)
+
+            yield {
+                'channel_path': 'dcos_generate_config.{}sh'.format(pkgpanda.util.variant_prefix(variant)),
+                'local_path': installer_filename
+            }
 
     # Build dcos-launch
     # TODO(cmaloney): This really doesn't belong to here, but it's the best place it fits for now.
     #                 dcos-launch works many places which aren't bash / on-premise installers.
     #                 It also isn't dependent on the "reproducible" artifacts at all. Just the commit...
-    yield {
-        'channel_path': 'dcos-launch',
-        'local_path': make_dcos_launch()
-    }
+    with logger.scope("building dcos-launch"):
+        yield {
+            'channel_path': 'dcos-launch',
+            'local_path': make_dcos_launch()
+        }

packages/dcos-image-deps/buildinfo.json

@@ -12,8 +12,9 @@
     "python-pyyaml",
     "python-requests",
     "python-retrying",
-    "six"
-    ],
+    "six",
+    "teamcity-messages"
+  ],
   "sources": {
     "aiohttp": {
       "kind": "url_extract",

packages/pkgpanda-api/buildinfo.json

@@ -2,6 +2,7 @@
   "requires": [
       "dcos-image",
       "python",
-      "python-gunicorn"
+      "python-gunicorn",
+      "teamcity-messages"
   ]
 }

packages/pytest/build

@@ -3,6 +3,4 @@ source /opt/mesosphere/environment.export
 export LIB_INSTALL_DIR="$PKG_PATH/lib/python3.5/site-packages"
 mkdir -p "$LIB_INSTALL_DIR"
 
-for package in pytest teamcity-messages; do
-  pip3 install --no-deps --install-option="--prefix=$PKG_PATH" --root=/ /pkg/src/$package
-done
+pip3 install --no-deps --install-option="--prefix=$PKG_PATH" --root=/ /pkg/src/$PKG_NAME

packages/pytest/buildinfo.json

@@ -1,15 +1,8 @@
 {
-  "requires": ["python"],
-  "sources": {
-    "pytest": {
-      "kind": "url_extract",
-      "url": "https://pypi.python.org/packages/a0/2f/076c816e2402c4911ccee4b93ba0475145b7cffd0320ca8efa0add7c469c/pytest-3.0.3.tar.gz",
-      "sha1": "e7fb899ecac031a84e66f991289203d3c1f7c6cb"
-    },
-    "teamcity-messages": {
-      "kind": "url_extract",
-      "url": "https://pypi.python.org/packages/69/0f/7ba789bcc0ad43b7d88582722b2dbeb0595d5f9b66e55fbc3e01bb771459/teamcity-messages-1.19.tar.gz",
-      "sha1": "6b7fe243a3db67577f3b5b3134850256e3df5aa2"
-    }
+  "requires": ["python", "teamcity-messages"],
+  "single_source": {
+    "kind": "url_extract",
+    "url": "https://pypi.python.org/packages/a0/2f/076c816e2402c4911ccee4b93ba0475145b7cffd0320ca8efa0add7c469c/pytest-3.0.3.tar.gz",
+    "sha1": "e7fb899ecac031a84e66f991289203d3c1f7c6cb"
   }
 }

packages/teamcity-messages/build

@@ -0,0 +1,6 @@
+#!/bin/bash
+source /opt/mesosphere/environment.export
+export LIB_INSTALL_DIR="$PKG_PATH/lib/python3.5/site-packages"
+mkdir -p "$LIB_INSTALL_DIR"
+
+pip3 install --no-deps --install-option="--prefix=$PKG_PATH" --root=/ /pkg/src/$PKG_NAME

packages/teamcity-messages/buildinfo.json

@@ -0,0 +1,8 @@
+{
+    "requires": ["python"],
+    "single_source": {
+        "kind": "url_extract",
+        "url": "https://pypi.python.org/packages/69/0f/7ba789bcc0ad43b7d88582722b2dbeb0595d5f9b66e55fbc3e01bb771459/teamcity-messages-1.19.tar.gz",
+        "sha1": "6b7fe243a3db67577f3b5b3134850256e3df5aa2"
+    }
+}

pkgpanda/build/__init__.py

@@ -20,8 +20,8 @@
 from pkgpanda.constants import RESERVED_UNIT_NAMES
 from pkgpanda.exceptions import FetchError, PackageError, ValidationError
 from pkgpanda.util import (check_forbidden_services, download_atomic, load_json,
-                           load_string, make_file, make_tar, rewrite_symlinks,
-                           write_json, write_string)
+                           load_string, logger, make_file, make_tar,
+                           rewrite_symlinks, write_json, write_string)
 
 
 class BuildError(Exception):
@@ -713,13 +713,13 @@ def visit_packages(package_tuples):
     else:
         package_sets = package_store.get_all_package_sets()
 
-    # Build all required packages for all tree variants.
-    for package_set in package_sets:
-        visit_packages(package_set.all_packages)
+    with logger.scope("resolve package graph"):
+        # Build all required packages for all tree variants.
+        for package_set in package_sets:
+            visit_packages(package_set.all_packages)
 
     built_packages = dict()
     for (name, variant) in build_order:
-        print("Building: {} variant {}".format(name, pkgpanda.util.variant_str(variant)))
         built_packages.setdefault(name, dict())
 
         # Run the build, store the built package path for later use.
@@ -732,16 +732,16 @@ def visit_packages(package_tuples):
 
     # Build bootstrap tarballs for all tree variants.
     def make_bootstrap(package_set):
-        print("Making bootstrap variant:", pkgpanda.util.variant_name(package_set.variant))
-        package_paths = list()
-        for name, pkg_variant in package_set.bootstrap_packages:
-            package_paths.append(built_packages[name][pkg_variant])
+        with logger.scope("Making bootstrap variant: {}".format(pkgpanda.util.variant_name(package_set.variant))):
+            package_paths = list()
+            for name, pkg_variant in package_set.bootstrap_packages:
+                package_paths.append(built_packages[name][pkg_variant])
 
-        if mkbootstrap:
-            return make_bootstrap_tarball(
-                package_store,
-                list(sorted(package_paths)),
-                package_set.variant)
+            if mkbootstrap:
+                return make_bootstrap_tarball(
+                    package_store,
+                    list(sorted(package_paths)),
+                    package_set.variant)
 
     # Build bootstraps and and package lists for all variants.
     # TODO(cmaloney): Allow distinguishing between "build all" and "build the default one".
@@ -826,8 +826,13 @@ def get_build_ids(self):
 
 
 def build(package_store, name, variant, clean_after_build, recursive=False):
+    msg = "Building package {} variant {}".format(name, pkgpanda.util.variant_name(variant))
+    with logger.scope(msg):
+        return _build(package_store, name, variant, clean_after_build, recursive)
+
+
+def _build(package_store, name, variant, clean_after_build, recursive):
     assert isinstance(package_store, PackageStore)
-    print("Building package {} variant {}".format(name, pkgpanda.util.variant_str(variant)))
     tmpdir = tempfile.TemporaryDirectory(prefix="pkgpanda_repo")
     repository = Repository(tmpdir.name)
 
@@ -1230,17 +1235,16 @@ def clean():
     # TODO(cmaloney): Move to an RAII wrapper.
     check_call(['rm', '-rf', install_dir])
 
-    print("Building package tarball")
-
-    # Check for forbidden services before packaging the tarball:
-    try:
-        check_forbidden_services(cache_abs("result"), RESERVED_UNIT_NAMES)
-    except ValidationError as ex:
-        raise BuildError("Package validation failed: {}".format(ex))
+    with logger.scope("Build package tarball"):
+        # Check for forbidden services before packaging the tarball:
+        try:
+            check_forbidden_services(cache_abs("result"), RESERVED_UNIT_NAMES)
+        except ValidationError as ex:
+            raise BuildError("Package validation failed: {}".format(ex))
 
-    # TODO(cmaloney): Updating / filling last_build should be moved out of
-    # the build function.
-    write_string(package_store.get_last_build_filename(name, variant), str(pkg_id))
+        # TODO(cmaloney): Updating / filling last_build should be moved out of
+        # the build function.
+        write_string(package_store.get_last_build_filename(name, variant), str(pkg_id))
 
     # Bundle the artifacts into the pkgpanda package
     tmp_name = pkg_path + "-tmp.tar.xz"

pkgpanda/build/src_fetchers.py

@@ -4,7 +4,7 @@
 from subprocess import CalledProcessError, check_call, check_output
 
 from pkgpanda.exceptions import ValidationError
-from pkgpanda.util import download_atomic, sha1
+from pkgpanda.util import download_atomic, logger, sha1
 
 
 # Ref must be a git sha-1. We then pass it through get_sha1 to make
@@ -104,8 +104,8 @@ def checkout_to(self, directory):
         except Exception as ex:
             raise ValidationError("Unable to find sha1 of ref_origin {}: {}".format(self.ref_origin, ex))
         if self.ref != origin_commit:
-            print(
-                "WARNING: Current ref doesn't match the ref origin. "
+            logger.warning(
+                "Current ref doesn't match the ref origin. "
                 "Package ref should probably be updated to pick up "
                 "new changes to the code:" +
                 " Current: {}, Origin: {}".format(self.ref,