From 83ecb97fec7efde09f543fb1f5ef65bd6d4f1011 Mon Sep 17 00:00:00 2001 From: Ian Wienand Date: Tue, 6 Feb 2018 10:03:34 +1100 Subject: [PATCH] Add VERBOSE_NO_TIMESTAMP flag As described in the documentation, this flag is intended for the case where the console output is being captured by a tool that appends its own timestamps. In the gate this is the job-output.txt. We want the console output as people like to watch that scrolling by as part of the live console log. Although this gets saved to job-output.txt, we still want to keep logging to the individual log files even though it's technically a duplicate -- in the multinode case the job-output.txt gets interleaved by all the running nodes; it's much easier to just look at the individual log files. Also, people are used to it where it is :) Change-Id: I3486636f1c76139581f6cd9668426f507b7c621d --- .zuul.yaml | 1 + doc/source/configuration.rst | 12 ++++++++++++ stack.sh | 7 ++++++- tools/outfilter.py | 27 ++++++++++++++++++++------- 4 files changed, 39 insertions(+), 8 deletions(-) diff --git a/.zuul.yaml b/.zuul.yaml index a90df2f06a..cc29466f35 100644 --- a/.zuul.yaml +++ b/.zuul.yaml @@ -66,6 +66,7 @@ LOGFILE: /opt/stack/logs/devstacklog.txt LOG_COLOR: false VERBOSE: true + VERBOSE_NO_TIMESTAMP: true NOVNC_FROM_PACKAGE: true ERROR_ON_CLONE: true # Gate jobs can't deal with nested virt. Disable it. diff --git a/doc/source/configuration.rst b/doc/source/configuration.rst index 49cad05554..1d02395058 100644 --- a/doc/source/configuration.rst +++ b/doc/source/configuration.rst @@ -286,6 +286,18 @@ see what is going on. This can be disabled with:: LOG_COLOR=False +When using the logfile, by default logs are sent to the console and +the file. You can set ``VERBOSE`` to ``false`` if you only wish the +logs to be sent to the file (this may avoid having double-logging in +some cases where you are capturing the script output and the log +files). If ``VERBOSE`` is ``true`` you can additionally set +``VERBOSE_NO_TIMESTAMP`` to avoid timestamps being added to each +output line sent to the console. This can be useful in some +situations where the console output is being captured by a runner or +framework (e.g. Ansible) that adds its own timestamps. Note that the +log lines sent to the ``LOGFILE`` will still be prefixed with a +timestamp. + Logging the Service Output ~~~~~~~~~~~~~~~~~~~~~~~~~~ diff --git a/stack.sh b/stack.sh index 9b496c0e20..1d1f12e116 100755 --- a/stack.sh +++ b/stack.sh @@ -405,6 +405,7 @@ is_package_installed python || install_package python # Set up logging level VERBOSE=$(trueorfalse True VERBOSE) +VERBOSE_NO_TIMESTAMP=$(trueorfalse False VERBOSE) # Draw a spinner so the user knows something is happening function spinner { @@ -470,8 +471,12 @@ if [[ -n "$LOGFILE" ]]; then # stdout later. exec 3>&1 if [[ "$VERBOSE" == "True" ]]; then + _of_args="-v" + if [[ "$VERBOSE_NO_TIMESTAMP" == "True" ]]; then + _of_args="$_of_args --no-timestamp" + fi # Set fd 1 and 2 to write the log file - exec 1> >( $TOP_DIR/tools/outfilter.py -v -o "${LOGFILE}" ) 2>&1 + exec 1> >( $TOP_DIR/tools/outfilter.py $_of_args -o "${LOGFILE}" ) 2>&1 # Set fd 6 to summary log file exec 6> >( $TOP_DIR/tools/outfilter.py -o "${SUMFILE}" ) else diff --git a/tools/outfilter.py b/tools/outfilter.py index 296cf8dfe5..cf091247d0 100755 --- a/tools/outfilter.py +++ b/tools/outfilter.py @@ -36,6 +36,13 @@ def get_options(): parser.add_argument('-o', '--outfile', help='Output file for content', default=None) + # NOTE(ianw): This is intended for the case where your stdout is + # being captured by something like ansible which independently + # logs timestamps on the lines it receives. Note that if using a + # output file, those log lines are still timestamped. + parser.add_argument('-b', '--no-timestamp', action='store_true', + help='Do not prefix stdout with timestamp (bare)', + default=False) parser.add_argument('-v', '--verbose', action='store_true', default=False) return parser.parse_args() @@ -61,17 +68,23 @@ def main(): if skip_line(line): continue - # This prevents us from nesting date lines, because - # we'd like to pull this in directly in Grenade and not double - # up on DevStack lines + # This prevents us from nesting date lines, because we'd like + # to pull this in directly in Grenade and not double up on + # DevStack lines. + # NOTE(ianw): we could actually strip the extra ts in "bare" + # mode (which came after this)? ... as we get more experience + # with zuulv3 native jobs and ansible capture it may become + # clearer what to do if HAS_DATE.search(line) is None: now = datetime.datetime.utcnow() - line = ("%s | %s" % ( + ts_line = ("%s | %s" % ( now.strftime("%Y-%m-%d %H:%M:%S.%f")[:-3], line)) + else: + ts_line = line if opts.verbose: - sys.stdout.write(line) + sys.stdout.write(line if opts.no_timestamp else ts_line) sys.stdout.flush() if outfile: @@ -80,9 +93,9 @@ def main(): # 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(line) + outfile.write(ts_line) else: - outfile.write(line.encode('utf-8')) + outfile.write(ts_line.encode('utf-8')) outfile.flush()