provide timestamps in grenade output

this is part of the effort to make grenade summaries actually work
in the gate like we expect, so that the base case can take the
output out of the main console and into summary consoles for
readability.

Instead of duplicating the awk filter from devstack, create a new
python tool for this, which lets us have much greater control and
sanity in filtering out garbage that we don't care about.

Change-Id: I235a725b6ca8a02caddad9f5a1457f6461269d5b

grenade.sh

@@ -96,15 +96,21 @@ if [[ -n "$LOGFILE" ]]; then
     # Copy stdout to fd 3
     exec 3>&1
     if [[ "$VERBOSE" == "True" ]]; then
+        echo "Running in verbose mode:"
+        echo "  Full logs found at => ${LOGFILE}"
+        echo "  Summary logs at => ${SUMFILE}"
         # Redirect stdout/stderr to tee to write the log file
-        exec 1> >( tee "${LOGFILE}" ) 2>&1
+        exec 1> >( ./tools/outfilter.py -v -o "${LOGFILE}" ) 2>&1
         # Set up a second fd for output
-        exec 6> >( tee "${SUMFILE}" )
+        exec 6> >( ./tools/outfilter.py -o "${SUMFILE}" )
     else
+        echo "Running in summary mode:"
+        echo "  Full logs found at => ${LOGFILE}"
+        echo "  Summary logs at => ${SUMFILE}"
         # Set fd 1 and 2 to primary logfile
-        exec 1> "${LOGFILE}" 2>&1
+        exec 1> >( ./tools/outfilter.py -o "${LOGFILE}") 2>&1
         # Set fd 6 to summary logfile and stdout
-        exec 6> >( tee "${SUMFILE}" /dev/fd/3 )
+        exec 6> >( ./tools/outfilter.py -v -o "${SUMFILE}" >&3)
     fi
 
     echo_summary "grenade.sh log $LOGFILE"
@@ -120,7 +126,7 @@ else
         exec 1>/dev/null 2>&1
     fi
     # Always send summary fd to original stdout
-    exec 6>&3
+    exec 6> >( ./tools/outfilter.py -v -o "${SUMFILE}" >&3)
 fi
 
 # Set up logging of screen windows

tools/outfilter.py

@@ -0,0 +1,87 @@
+#!/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)')
+HAS_DATE = re.compile('^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3} \|')
+
+
+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',
+                        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, 'a', 0)
+
+    # otherwise fileinput reprocess args as files
+    sys.argv = []
+    while True:
+        line = sys.stdin.readline()
+        if not line:
+            return 0
+
+        # put skip lines here
+        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
+        if HAS_DATE.search(line) is None:
+            now = datetime.datetime.utcnow()
+            line = ("%s | %s" % (
+                now.strftime("%Y-%m-%d %H:%M:%S.%f")[:-3],
+                line))
+
+        if opts.verbose:
+            sys.stdout.write(line)
+            sys.stdout.flush()
+        if outfile:
+            outfile.write(line)
+            outfile.flush()
+
+
+if __name__ == '__main__':
+    try:
+        sys.exit(main())
+    except KeyboardInterrupt:
+        sys.exit(1)