From 60862892f674357e4de4e6fab31966a4b00e00a7 Mon Sep 17 00:00:00 2001
From: Sean Dague <sean.dague@samsung.com>
Date: Sun, 23 Feb 2014 08:09:04 -0500
Subject: [PATCH] timestamp sublogs

the sublogs really need timestamps so they can be indexed in
logstash, and we can then actually understand when things might
be failing.

basic logic brought in from devstack, with some changes for
millisecond timing.

Change-Id: Iede34b970d090f855c701b69c1f5167a08ab9c52
---
 devstack-vm-gate-wrap.sh | 14 +++++++-------
 functions.sh             | 13 +++++++++++++
 2 files changed, 20 insertions(+), 7 deletions(-)

diff --git a/devstack-vm-gate-wrap.sh b/devstack-vm-gate-wrap.sh
index 6ebb192c..a4c6b240 100755
--- a/devstack-vm-gate-wrap.sh
+++ b/devstack-vm-gate-wrap.sh
@@ -259,15 +259,15 @@ ip neighbor show
 echo "Available disk space on this host:"
 df -h
 
-setup_host &> $WORKSPACE/logs/devstack-gate-setup-host.txt
+tsfilter setup_host &> $WORKSPACE/logs/devstack-gate-setup-host.txt
 
 if [ "$DEVSTACK_GATE_GRENADE" -eq "1" -o "$DEVSTACK_GATE_GRENADE_FORWARD" -eq "1" ]; then
-    setup_workspace $GRENADE_NEW_BRANCH $BASE/new &> \
+    tsfilter setup_workspace $GRENADE_NEW_BRANCH $BASE/new &> \
         $WORKSPACE/logs/devstack-gate-setup-workspace-new.txt
-    setup_workspace $GRENADE_OLD_BRANCH $BASE/old &> \
+    tsfilter setup_workspace $GRENADE_OLD_BRANCH $BASE/old &> \
         $WORKSPACE/logs/devstack-gate-setup-workspace-old.txt
 else
-    setup_workspace $OVERRIDE_ZUUL_BRANCH $BASE/new &> \
+    tsfilter setup_workspace $OVERRIDE_ZUUL_BRANCH $BASE/new &> \
         $WORKSPACE/logs/devstack-gate-setup-workspace-new.txt
 fi
 
@@ -280,7 +280,7 @@ fi
 # Run pre test hook if we have one
 if function_exists "pre_test_hook"; then
   set -o xtrace
-  pre_test_hook 2>&1 | tee $WORKSPACE/devstack-gate-pre-test-hook.txt
+  tsfilter pre_test_hook | tee $WORKSPACE/devstack-gate-pre-test-hook.txt
   sudo mv $WORKSPACE/devstack-gate-pre-test-hook.txt $BASE/logs/
   set +o xtrace
 fi
@@ -293,7 +293,7 @@ RETVAL=$GATE_RETVAL
 # Run post test hook if we have one
 if [ $GATE_RETVAL -eq 0 ] && function_exists "post_test_hook"; then
   set -o xtrace -o pipefail
-  post_test_hook 2>&1 | tee $WORKSPACE/devstack-gate-post-test-hook.txt
+  tsfilter post_test_hook | tee $WORKSPACE/devstack-gate-post-test-hook.txt
   RETVAL=$?
   sudo mv $WORKSPACE/devstack-gate-post-test-hook.txt $BASE/logs/
   set +o xtrace +o pipefail
@@ -305,7 +305,7 @@ if [ $GATE_RETVAL -eq 137 ] && [ -f $WORKSPACE/gate.pid ] ; then
     sudo kill -s 9 -${GATEPID}
 fi
 
-cleanup_host &> $WORKSPACE/devstack-gate-cleanup-host.txt
+tsfilter cleanup_host &> $WORKSPACE/devstack-gate-cleanup-host.txt
 sudo mv $WORKSPACE/devstack-gate-cleanup-host.txt $BASE/logs/
 
 exit $RETVAL
diff --git a/functions.sh b/functions.sh
index 00605974..ed7c6868 100644
--- a/functions.sh
+++ b/functions.sh
@@ -20,6 +20,19 @@ function function_exists {
     type $1 2>/dev/null | grep -q 'is a function'
 }
 
+# awk filter to timestamp the stream, including stderr merging
+function tsfilter {
+    $@ 2>&1 | awk '
+    {
+        cmd ="date +\"%Y-%m-%d %H:%M:%S.%3N | \""
+        cmd | getline now
+        close("date +\"%Y-%m-%d %H:%M:%S.%3N | \"")
+        sub(/^/, now)
+        print
+        fflush()
+    }'
+}
+
 # Attempt to fetch a git ref for a project, if that ref is not empty
 function git_fetch_at_ref {
     local project=$1