From f60dd384827beb8ec193ac7738e973941fc8b6d5 Mon Sep 17 00:00:00 2001 From: Ian Wienand Date: Fri, 16 Jun 2017 12:09:24 +1000 Subject: [PATCH] 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 | 2 +- diskimage_builder/lib/disk-image-create | 29 +++++- diskimage_builder/lib/outfilter.py | 89 +++++++++++++++++++ diskimage_builder/logging_config.py | 6 +- .../notes/timestamp-43015aa5434e8ddb.yaml | 14 +++ setup.cfg | 2 + tests/run_functests.sh | 4 +- 7 files changed, 138 insertions(+), 8 deletions(-) create mode 100644 diskimage_builder/lib/outfilter.py create mode 100644 releasenotes/notes/timestamp-43015aa5434e8ddb.yaml diff --git a/diskimage_builder/lib/dib-run-parts b/diskimage_builder/lib/dib-run-parts index 0f81be195..dc5748647 100755 --- a/diskimage_builder/lib/dib-run-parts +++ b/diskimage_builder/lib/dib-run-parts @@ -36,7 +36,7 @@ usage() { output_prefix() { - printf "%s %s " "${name}" "$(date)" >&2 + printf "%s " "${name}" >&2 } output () { diff --git a/diskimage_builder/lib/disk-image-create b/diskimage_builder/lib/disk-image-create index cb36d3f5f..5d41c5e50 100644 --- a/diskimage_builder/lib/disk-image-create +++ b/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 { diff --git a/diskimage_builder/lib/outfilter.py b/diskimage_builder/lib/outfilter.py new file mode 100644 index 000000000..728bcf402 --- /dev/null +++ b/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) diff --git a/diskimage_builder/logging_config.py b/diskimage_builder/logging_config.py index 2429dfb46..f1e223840 100644 --- a/diskimage_builder/logging_config.py +++ b/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' } diff --git a/releasenotes/notes/timestamp-43015aa5434e8ddb.yaml b/releasenotes/notes/timestamp-43015aa5434e8ddb.yaml new file mode 100644 index 000000000..ab6e5c1aa --- /dev/null +++ b/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. \ No newline at end of file diff --git a/setup.cfg b/setup.cfg index 8b9fbe708..63c8bda48 100644 --- a/setup.cfg +++ b/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 = diff --git a/tests/run_functests.sh b/tests/run_functests.sh index 9e3ca9cc7..1efd7e995 100755 --- a/tests/run_functests.sh +++ b/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 - log="$(date +"%Y%m%d-%H%M%S.%N") ${log}" - fi + # note: dib logs have timestamp by default now echo "${log}" done }