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

@@ -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.

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
 ~~~~~~~~~~~~~~~~~~~~~~~~~~
 

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

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()