From b343155815716094a70c5428c26ddcb0980a031e Mon Sep 17 00:00:00 2001 From: Ravishankar N Date: Sat, 9 May 2015 07:23:09 +0530 Subject: 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 Reviewed-on: http://review.gluster.org/10667 Tested-by: NetBSD Build System Reviewed-by: Kaleb KEITHLEY Reviewed-by: Raghavendra Talur --- tests/include.rc | 24 +++++++++++++++++++++--- 1 file changed, 21 insertions(+), 3 deletions(-) (limited to 'tests') 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 -- cgit