Add timestamp output filter

This adds a devstack-inspired output filter to standardise
timestamping.

Currently, python tools timestamp always (timestamp setup in
logging_config.py) but all the surrounding bash does not.

We have extra timestamps added in run_functests.sh for our own
purposes to get the bash timestamps; but this ends up giving us
double-timestamps for the python bits.  Additionally, callers such as
nodepool capture our output and put their own timestamps on it, and
again have the double-timestamps.

This uses a lightly modified outfilter.py from devstack to standardise
this.

All output is run through this filter, which will timestamp it.  I
have removed the places where we double-timestamp -- logging_config.py
and the prefix in dib-run-parts.

An env option is added to turn timestamps off completely (does not
seem worth taking up a command-line option for).  For callers like
nodepool, they can set this and will just have their own timestamps as
they collect the lines.

Since all logging is going through outfilter, it's easy to add a
--logfile option.  I think this will be quite handy; personally I'm
always redirecting dib runs to files for debugging.

I've also added a "quiet" option.  I think this could be useful in
run_tests.sh if we were to start logging the output of each test to
individual files.  This would be much easier to deal with than the
very large log files we get (especially if we wanted to turn on
parallel running...)

Change-Id: I202e1cb200bde17f6d7770cf1e2710bbf4cca64c

diskimage_builder/lib/dib-run-parts

@@ -36,7 +36,7 @@ usage() {
 
 
 output_prefix() {
-    printf "%s %s " "${name}" "$(date)" >&2
+    printf "%s " "${name}" >&2
 }
 
 output () {

diskimage_builder/lib/disk-image-create

@@ -59,6 +59,7 @@ function show_options () {
     echo "    -x -- turn on tracing (use -x -x for very detailed tracing)."
     echo "    -u -- uncompressed; do not compress the image - larger but faster"
     echo "    -c -- clear environment before starting work"
+    echo "    --logfile -- save run output to given logfile"
     echo "    --checksum -- generate MD5 and SHA256 checksum files for the created image"
     echo "    --image-size size -- image size in GB for the created image"
     echo "    --image-cache directory -- location for cached images(default ~/.cache/image-create)"
@@ -88,7 +89,12 @@ function show_options () {
     echo "    -h|--help -- display this help and exit"
     echo "    --version -- display version and exit"
     echo
-    echo "ELEMENTS_PATH will allow you to specify multiple locations for the elements."
+    echo "Environment Variables:"
+    echo "  (this is not a complete list)"
+    echo
+    echo "  * ELEMENTS_PATH: specify external locations for the elements.  As for \$PATH"
+    echo "  * DIB_NO_TIMESTAMP: no timestamp prefix on output.  Useful if capturing output"
+    echo "  * DIB_QUIET: do not output log output to stdout.  See --logfile"
     echo
     echo "NOTE: At least one distribution root element must be specified."
     echo
@@ -120,7 +126,8 @@ DIB_DEFAULT_INSTALLTYPE=${DIB_DEFAULT_INSTALLTYPE:-"source"}
 MKFS_OPTS=""
 ACI_MANIFEST=${ACI_MANIFEST:-}
 DOCKER_TARGET=""
-TEMP=`getopt -o a:ho:t:xucnp: -l checksum,no-tmpfs,offline,help,version,min-tmpfs:,image-size:,image-cache:,max-online-resize:,mkfs-options:,qemu-img-options:,ramdisk-element:,root-label:,install-type:,docker-target: -n $SCRIPTNAME -- "$@"`
+LOGFILE=""
+TEMP=`getopt -o a:ho:t:xucnp: -l checksum,no-tmpfs,offline,help,version,min-tmpfs:,image-size:,image-cache:,max-online-resize:,mkfs-options:,qemu-img-options:,ramdisk-element:,root-label:,install-type:,docker-target:,logfile: -n $SCRIPTNAME -- "$@"`
 if [ $? -ne 0 ] ; then echo "Terminating..." >&2 ; exit 1 ; fi
 
 # Note the quotes around `$TEMP': they are essential!
@@ -151,6 +158,7 @@ while true ; do
         --ramdisk-element) RAMDISK_ELEMENT=$2; shift 2;;
         --install-type) DIB_DEFAULT_INSTALLTYPE=$2; shift 2;;
         --docker-target) export DOCKER_TARGET=$2; shift 2 ;;
+        --logfile) export LOGFILE=$2; shift 2 ;;
         --) shift ; break ;;
         *) echo "Internal error!" ; exit 1 ;;
     esac
@@ -167,6 +175,23 @@ if [ "$CLEAR_ENV" = "1" -a "$HOME" != "" ]; then
   exec -c $0 "$@"
 fi
 
+# We send stdout & stderr through "outfilter" which does timestamping,
+# basic filtering and log file output.
+_TS_FLAG=""
+if [[ "${DIB_NO_TIMESTAMP:-0}" -eq 1 ]]; then
+    _TS_FLAG="--no-timestamp"
+fi
+_QUIET_FLAG="-v"
+if [[ "${DIB_QUIET:-0}" -eq 1 ]]; then
+    _QUIET_FLAG=""
+fi
+_LOGFILE_FLAG=""
+if [[ -n "${LOGFILE}" ]]; then
+    echo "Output logs going to: ${LOGFILE}"
+    _LOGFILE_FLAG="-o ${LOGFILE}"
+fi
+exec 1> >( ${DIB_PYTHON_EXEC:-python} $_LIB/outfilter.py ${_TS_FLAG} ${_QUIET_FLAG} ${_LOGFILE_FLAG} ) 2>&1
+
 
 # Display the current file/function/line in the debug output
 function _ps4 {

diskimage_builder/lib/outfilter.py

@@ -0,0 +1,89 @@
+#!/usr/bin/env python
+#
+# Copyright 2014 Hewlett-Packard Development Company, L.P.
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+# This is an output filter to filter and timestamp the logs from Grenade and
+# DevStack. Largely our awk filters got beyond the complexity level which were
+# sustainable, so this provides us much more control in a single place.
+#
+# The overhead of running python should be less than execing `date` a million
+# times during a run.
+
+import argparse
+import datetime
+import re
+import sys
+
+IGNORE_LINES = re.compile('(set \+o|xtrace)')
+
+
+def get_options():
+    parser = argparse.ArgumentParser(
+        description='Filter output by DevStack and friends')
+    parser.add_argument('-o', '--outfile',
+                        help='Output file for content',
+                        default=None)
+    parser.add_argument('-v', '--verbose', action='store_true',
+                        help='Write to stdout',
+                        default=False)
+    parser.add_argument('-b', '--no-timestamp', action='store_true',
+                        help='Do not prefix stdout with timestamp (bare)',
+                        default=False)
+    return parser.parse_args()
+
+
+def skip_line(line):
+    """Should we skip this line."""
+    return IGNORE_LINES.search(line) is not None
+
+
+def main():
+    opts = get_options()
+    outfile = None
+    if opts.outfile:
+        outfile = open(opts.outfile, 'ab', 0)
+
+    # Otherwise fileinput reprocess args as files
+    sys.argv = []
+    for line in iter(sys.stdin.readline, ''):
+        # put skip lines here
+        if skip_line(line):
+            continue
+
+        now = datetime.datetime.utcnow()
+        ts_line = ("%s | %s" % (
+            now.strftime("%Y-%m-%d %H:%M:%S.%f")[:-3],
+            line))
+
+        if opts.verbose:
+            sys.stdout.write(line if opts.no_timestamp else ts_line)
+            sys.stdout.flush()
+        if outfile:
+            # We've opened outfile as a binary file to get the
+            # non-buffered behaviour.  on python3, sys.stdin was
+            # opened with the system encoding and made the line into
+            # utf-8, so write the logfile out in utf-8 bytes.
+            if sys.version_info < (3,):
+                outfile.write(ts_line)
+            else:
+                outfile.write(ts_line.encode('utf-8'))
+            outfile.flush()
+
+
+if __name__ == '__main__':
+    try:
+        sys.exit(main())
+    except KeyboardInterrupt:
+        sys.exit(1)

diskimage_builder/logging_config.py

@@ -65,11 +65,13 @@ def setup():
         'version': 1,
         'disable_existing_loggers': False,
 
+        # note that disk-image-create runs stdout through
+        # outfilter.py, which adds the timestamp.  this doesn't have a
+        # timestamp to avoid double logging
         'formatters': {
             'standard': {
                 '()': 'diskimage_builder.logging_config.DibFormatter',
-                'datefmt': '%Y-%m-%d %H:%M:%S',
+                'fmt': '%(levelname)s '
-                'fmt': '%(asctime)s.%(msecs)03d %(levelname)s '
                 '%(name)s [-] %(message)s',
                 'debug_suffix': ' %(funcName)s %(pathname)s:%(lineno)d'
             }

releasenotes/notes/timestamp-43015aa5434e8ddb.yaml

@@ -0,0 +1,14 @@
+---
+features:
+  - A ``--logfile`` option is added to save output to a given file.
+
+  - By default, all ``stdout`` will log with timestamps (this used to
+    be inconsistent; python tools logged with a timestamp, and bash
+    parts did not).  If you set ``DIB_NO_TIMESTAMP`` to ``1`` the
+    timestamp prefix will be suppressed (this would be appropriate if
+    you are running diskimage-builder and capturing its output, and
+    adding your own timestamp).  Note that output to ``--logfile``
+    will always be timestamped.
+
+  - You can set ``DIB_QUIET`` to ``1`` to suppress all output.  This
+    is likely only useful when used with the ``--logfile`` command.

setup.cfg

@@ -29,6 +29,8 @@ autodoc_exclude_modules =
      diskimage_builder.block_device.tests.*
      # elements are a weird mix of scripts & python
      diskimage_builder.elements.*
+     # this is non-pythony stuff
+     diskimage_builder.lib.*
 
 [files]
 packages =

tests/run_functests.sh

@@ -49,9 +49,7 @@ function log_with_prefix {
 
     while read a; do
         log="[$pr] $a"
-        if [[ ${LOG_DATESTAMP} -ne 0 ]]; then
+        # note: dib logs have timestamp by default now
-            log="$(date +"%Y%m%d-%H%M%S.%N") ${log}"
-        fi
         echo "${log}"
     done
 }