Cleaner logging

Remove vecho and vvecho, add vlog and vvlog instead.
log, vlog and vvlog are now wrappers around _log which handles verbose
levels better, for both terminal and log file.
Add LOGVERBOSE as a possible over-ride variable for a test script,
defaulting to VERBOSE + 1.

Change-Id: Iabba9b87de1ad1f8f4e287ed6574741dc7dc6e8f

1 files changed, 36 insertions, 29 deletions

diff --git a/test/test-common b/test/test-common
index ad68610..3fac84c 100755
--- a/test/test-common
+++ b/test/test-common
@@ -13,6 +13,9 @@ TOPDIR=$(dirname $0)/..
 if [ "$VERBOSE"x = ""x ] ; then
     VERBOSE=0
 fi
+if [ "$LOGVERBOSE"x = ""x ] ; then
+    LOGVERBOSE=$(($VERBOSE + 1))
+fi
 if [ "$HOSTS"x = ""x ] ; then
    HOSTS="panda01 panda02 panda03 arndale01 arndale02 arndale03 arndale04 imx5301 imx5302 imx5303"
 fi
@@ -34,40 +37,44 @@ imx5301_SWITCH_PORT="vlandswitch05:1/0/21"
 imx5302_SWITCH_PORT="vlandswitch05:1/0/22"
 imx5303_SWITCH_PORT="vlandswitch04:Gi1/0/2"
 
-# Function for output; write text to terminal and to our logfile, with
-# timestamp for sorting.
-log () {
+# Function for output; write text to our logfile and (optionally) the
+# terminal, with timestamp for sorting.
+_log () {
     DATE=$(date -u +%F/%H:%M:%S.%N)
     if [ "${LOGFILE}"x = ""x ] ; then
 	LOGFILE=$0.log
     fi
-    if [ $VERBOSE -gt 0 ] ; then
+    LEVEL=$1
+    shift
+    if [ $VERBOSE -gt $LEVEL ] ; then
 	echo "${DATE}: $@" >&2 # Use stderr so we don't confuse
 	                       # anybody reading our output
     fi
-    echo "   ${DATE}: $@" >> ${LOGFILE}
+    if [ $LOGVERBOSE -gt $LEVEL ] ; then
+	echo "   ${DATE}: $@" >> ${LOGFILE}
+    fi
 }
 
-vecho () {
-    if [ $VERBOSE -gt 0 ] ; then
-	log "$@"
-    fi
+log () {
+    _log 0 $@
 }
 
-vvecho () {
-    if [ $VERBOSE -gt 1 ] ; then
-	log "$@"
-    fi
+vlog () {
+    _log 1 $@
+}
+
+vvlog () {
+    _log 2 $@
 }
 
 # Run a vland admin command, and optionally log both the full text of
 # the command and its output
 run_admin_command () {
     ADMIN="python $TOPDIR/admin.py"
-    vvecho "Running \"$ADMIN $@\""
+    vlog "Running \"$ADMIN $@\""
     LAST_COMMAND="$@"
     RESULT=$($ADMIN $@)
-    vvecho "  Result is \"$RESULT\""
+    vlog "  Result is \"$RESULT\""
     echo $RESULT
 }
 
@@ -79,10 +86,10 @@ verify_host_is_base () {
     CURRENT_VLAN_TAG=$(run_admin_command --show_vlan_tag $CURRENT_VLAN_ID)
     BASE_VLAN_ID=$(run_admin_command --get_port_base_vlan $PORT_ID)
     BASE_VLAN_TAG=$(run_admin_command --show_vlan_tag $BASE_VLAN_ID)
-    vecho "$HOST"
-    vecho "  is on port ID $PORT_ID"
-    vecho "  which is on VLAN ID $CURRENT_VLAN_ID, tag $CURRENT_VLAN_TAG"
-    vecho "  and should be on base VLAN ID $BASE_VLAN_ID, tag $BASE_VLAN_TAG"
+    vlog "$HOST"
+    vlog "  is on port ID $PORT_ID"
+    vlog "  which is on VLAN ID $CURRENT_VLAN_ID, tag $CURRENT_VLAN_TAG"
+    vlog "  and should be on base VLAN ID $BASE_VLAN_ID, tag $BASE_VLAN_TAG"
     if [ $CURRENT_VLAN_ID == $BASE_VLAN_ID ] ; then
 	return 0
     else
@@ -103,41 +110,41 @@ verify_all_hosts_are_base () {
 all_hosts () {
     COMMAND="$@"
     for HOST in ${HOSTS}; do
-    	vvecho "Running on ${HOST}:: ${COMMAND}"
+    	vvlog "Running on ${HOST}:: ${COMMAND}"
         ssh linaro@${HOST} "${COMMAND}"
     done
 }
 
 start_logging () {
-    vecho "Starting logging on hosts"
+    log "Starting logging on hosts"
     all_hosts "echo HOSTS=\\\"$HOSTS\\\" > test-config"
 }
 
 stop_logging () {
-    vecho "Stopping logging on hosts"
+    log "Stopping logging on hosts"
     all_hosts "rm -f test-config"
 }
 
 grab_logs () {
-    vecho "Grabbing logs"
+    log "Grabbing logs"
     all_hosts "cat /tmp/ping-log*"
 }
 
 clear_logs () {
-    vecho "Clearing old logs on hosts"
+    log "Clearing old logs on hosts"
     all_hosts "rm -f /tmp/ping-log*"
 }
 
 pause () {
-    vecho "Pausing $1 seconds for systems to settle and/or log results"
+    log "Pausing $1 seconds for systems to settle and/or log results"
     sleep $1
 }
 
 cleanup () {
     error=$?
     if [ $error -ne 0 ] ; then
-	echo "Test script aborted with error $error - check logs for the failure"
-	echo "  Last VLANd command appears to be \"$LAST_COMMAND\""
+	_log -1 "Test script aborted with error $error - check logs for the failure"
+	_log -1 "  Last VLANd command appears to be \"$LAST_COMMAND\""
     fi
 }
 
@@ -251,8 +258,8 @@ trap cleanup 0
 #####################
 
 echo "Running test $NAME:"
-echo "($DESCRIPTION)"
-echo "Logging to ${LOGFILE}"
+echo "  ($DESCRIPTION)"
+echo "  Logging to ${LOGFILE}"
 
 # Startup check
 STATUS=$(run_admin_command --status)