diff --git a/diskimage_builder/lib/dib-run-parts b/diskimage_builder/lib/dib-run-parts index 0f81be19..dc574864 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 cb36d3f5..5d41c5e5 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 00000000..728bcf40 --- /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 2429dfb4..f1e22384 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 00000000..ab6e5c1a --- /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 8b9fbe70..63c8bda4 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 9e3ca9cc..1efd7e99 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 }