Merge "Add timestamp output filter"

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': '%(asctime)s.%(msecs)03d %(levelname)s '
+                'fmt': '%(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

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