tests: Add the command being 'TEST'ed in all gluster logs

Appends all commands being run under the test framework into the logs
with time stamps. Its a hack but I find it very useful to see what
sections of the logs (across all logs) need to be analysed between
execution of 2 commands.

Here's a sample output:
[2015-06-26 13:25:15.866764479]:++++++++++ G_LOG:tests/basic/afr/quorum.t: TEST: 46 ! test_write ++++++++++
[2015-06-26 13:25:15.872002] I [afr-common.c:1682:afr_local_discovery_cbk] 0-patchy-replicate-0: selecting local read_child patchy-client-1
[2015-06-26 13:25:15.874559] W [fuse-bridge.c:723:fuse_truncate_cbk] 0-glusterfs-fuse: 81: TRUNCATE() /a => -1 (Read-only file system)
[2015-06-26 13:25:15.880554623]:++++++++++ G_LOG:tests/basic/afr/quorum.t: TEST: 47 abc cat /mnt/glusterfs/0/b ++++++++++
[2015-06-26 13:25:15.897767878]:++++++++++ G_LOG:tests/basic/afr/quorum.t: TEST: 48 gluster --mode=script --wignore volume set patchy cluster.quorum-reads on ++++++++++[2015-06-26 13:25:15.994410] I [glusterfsd-mgmt.c:51:mgmt_cbk_spec] 0-mgmt: Volume file changed
[2015-06-26 13:25:17.098519] I [glusterfsd-mgmt.c:51:mgmt_cbk_spec] 0-mgmt: Volume file changed
[2015-06-26 13:25:17.099241] I [glusterfsd-mgmt.c:51:mgmt_cbk_spec] 0-mgmt: Volume file changed
[2015-06-26 13:25:17.099685] I [glusterfsd-mgmt.c:51:mgmt_cbk_spec] 0-mgmt: Volume file changed
[2015-06-26 13:25:17.100055] I [glusterfsd-mgmt.c:51:mgmt_cbk_spec] 0-mgmt: Volume file changed
[2015-06-26 13:25:17.105896] W [MSGID: 108003] [afr.c:94:fix_quorum_options] 0-patchy-replicate-0: quorum-type auto overriding quorum-count 2
[2015-06-26 13:25:17.105936] W [MSGID: 108001] [afr.c:189:reconfigure] 0-patchy-replicate-0: Client-quorum is not met
[2015-06-26 13:25:17.107438] I [glusterfsd-mgmt.c:1507:mgmt_getspec_cbk] 0-glusterfs: No change in volfile, continuing
[2015-06-26 13:25:17.108724] I [glusterfsd-mgmt.c:1507:mgmt_getspec_cbk] 0-glusterfs: No change in volfile, continuing
[2015-06-26 13:25:17.110082] I [glusterfsd-mgmt.c:1507:mgmt_getspec_cbk] 0-glusterfs: No change in volfile, continuing
[2015-06-26 13:25:17.110599] I [glusterfsd-mgmt.c:1507:mgmt_getspec_cbk] 0-glusterfs: No change in volfile, continuing
[2015-06-26 13:25:17.109678070]:++++++++++ G_LOG:tests/basic/afr/quorum.t: TEST: 49 1 mount_get_option_value /mnt/glusterfs/0 patchy-replicate-0 quorum-reads ++++++++++
[2015-06-26 13:25:17.117801] I [afr-common.c:1682:afr_local_discovery_cbk] 0-patchy-replicate-0: selecting local read_child patchy-client-1

Change-Id: Ib51284a0384508350579babaf1ae69cb372e0baa
BUG: 1233018
Signed-off-by: Ravishankar N <ravishankar@redhat.com>
Reviewed-on: http://review.gluster.org/10667
Tested-by: NetBSD Build System <jenkins@build.gluster.org>
Reviewed-by: Kaleb KEITHLEY <kkeithle@redhat.com>
Reviewed-by: Raghavendra Talur <rtalur@redhat.com>

1 files changed, 21 insertions, 3 deletions

diff --git a/tests/include.rc b/tests/include.rc
index 32d60b43348..1272cdecbda 100644
--- a/tests/include.rc
+++ b/tests/include.rc
@@ -122,6 +122,21 @@ function dbg()
         [ "x$DEBUG" = "x0" ] || echo "$*" >&2;
 }
 
+function G_LOG()
+{
+     local logdir=`$CLI --print-logdir`
+     test -d $logdir
+     if [ $? != 0 ]; then
+        return
+     fi
+     local string="++++++++++ G_LOG:$0: TEST: $1 $2 ++++++++++"
+     string="`date -u +["%F %T.%N"]`:$string"
+     local i
+     for i in `find $logdir/ -type f`;
+        do
+                echo $string>>$i
+        done
+}
 
 function test_header()
 {
@@ -174,6 +189,7 @@ function _EXPECT()
         shift;
         local a=""
 
+        G_LOG $TESTLINE "$*";
         test_header "$@";
 
         e="$1";
@@ -207,6 +223,7 @@ function _EXPECT_NOT()
         shift;
         local a=""
 
+        G_LOG $TESTLINE "$*";
         test_header "$@";
 
         e="$1";
@@ -224,7 +241,7 @@ function _EXPECT_KEYWORD()
 {
         TESTLINE=$1;
         shift;
-
+        G_LOG $TESTLINE "$*";
         test_header "$@";
 
         e="$1";
@@ -234,13 +251,13 @@ function _EXPECT_KEYWORD()
         test_footer;
 }
 
-
 function _TEST()
 {
         TESTLINE=$1;
         shift;
         local redirect=""
 
+        G_LOG $TESTLINE "$*";
         test_header "$@";
 
         if [ "$1" = "!" ]; then
@@ -260,6 +277,7 @@ function _EXPECT_WITHIN()
         local timeout=$1
         shift;
 
+        G_LOG $TESTLINE "$*";
         test_header "$@"
 
         e=$1;
@@ -826,7 +844,7 @@ log_newer()
         logdir=`$CLI --print-logdir`
 
         IFS="["
-        for date in `grep -hr "$msg" $logdir | awk -F '[\]]' '{print $1}'` ; do
+        for date in `grep -hr "$msg" $logdir | grep -v "G_LOG" | awk -F '[\]]' '{print $1}'` ; do
                 if [ `date -d "$date" +%s` -gt $ts ] ; then
                         return 0;
                 fi