Whamcloud - gitweb
b=22075 buffalo-v2 should detect test timeouts
[fs/lustre-release.git] / lustre / tests / test-framework.sh
index d3dbb63..3a9573e 100644 (file)
@@ -22,6 +22,7 @@ export QUOTA_AUTO=1
 # function used by scripts run on remote nodes
 LUSTRE=${LUSTRE:-$(cd $(dirname $0)/..; echo $PWD)}
 . $LUSTRE/tests/functions.sh
+. $LUSTRE/tests/yaml.sh
 
 LUSTRE_TESTS_CFG_DIR=${LUSTRE_TESTS_CFG_DIR:-${LUSTRE}/tests/cfg}
 
@@ -33,6 +34,9 @@ if [ -f "$EXCEPT_LIST_FILE" ]; then
     . $EXCEPT_LIST_FILE
 fi
 
+[ -z "$MODPROBECONF" -a -f /etc/modprobe.conf ] && MODPROBECONF=/etc/modprobe.conf
+[ -z "$MODPROBECONF" -a -f /etc/modprobe.d/Lustre ] && MODPROBECONF=/etc/modprobe.d/Lustre
+
 assert_DIR () {
     local failed=""
     [[ $DIR/ = $MOUNT/* ]] || \
@@ -54,17 +58,17 @@ usage() {
 
 print_summary () {
     trap 0
-    [ "$TESTSUITE" == "lfscktest" ] && return 0
+    [ "$TESTSUITE" == "lfsck" ] && return 0
     [ -n "$ONLY" ] && echo "WARNING: ONLY is set to ${ONLY}."
     local form="%-13s %-17s %s\n"
     printf "$form" "status" "script" "skipped tests E(xcluded) S(low)"
     echo "------------------------------------------------------------------------------------"
-    for O in $TESTSUITE_LIST; do
+    for O in $DEFAULT_SUITES; do
         local skipped=""
         local slow=""
-        local o=$(echo $O | tr "[:upper:]" "[:lower:]")
+        O=$(echo $O  | tr "-" "_" | tr "[:lower:]" "[:upper:]")
+        local o=$(echo $O  | tr "[:upper:]" "[:lower:]")
         o=${o//_/-}
-        o=${o//tyn/tyN}
         local log=${TMP}/${o}.log
         [ -f $log ] && skipped=$(grep excluded $log | awk '{ printf " %s", $3 }' | sed 's/test_//g')
         [ -f $log ] && slow=$(grep SLOW $log | awk '{ printf " %s", $3 }' | sed 's/test_//g')
@@ -74,7 +78,8 @@ print_summary () {
 
     done
 
-    for O in $TESTSUITE_LIST; do
+    for O in $DEFAULT_SUITES; do
+        O=$(echo $O  | tr "-" "_" | tr "[:lower:]" "[:upper:]")
         if [ "${!O}" = "no" ]; then
             # FIXME.
             # only for those tests suits which are run directly from acc-sm script:
@@ -87,7 +92,8 @@ print_summary () {
         fi
     done
 
-    for O in $TESTSUITE_LIST; do
+    for O in $DEFAULT_SUITES; do
+        O=$(echo $O  | tr "-" "_" | tr "[:lower:]" "[:upper:]")
         [ "${!O}" = "done" -o "${!O}" = "no" ] || \
             printf "$form" "UNFINISHED" "$O" ""
     done
@@ -109,6 +115,10 @@ init_test_env() {
     #[ -d /r ] && export ROOT=${ROOT:-/r}
     export TMP=${TMP:-$ROOT/tmp}
     export TESTSUITELOG=${TMP}/${TESTSUITE}.log
+    if [[ -z $LOGDIRSET ]]; then
+        export LOGDIR=${LOGDIR:-${TMP}/test_logs/}/$(date +%s)
+        export LOGDIRSET=true
+    fi
     export HOSTNAME=${HOSTNAME:-`hostname`}
     if ! echo $PATH | grep -q $LUSTRE/utils; then
         export PATH=$PATH:$LUSTRE/utils
@@ -117,12 +127,14 @@ init_test_env() {
         export PATH=$PATH:$LUSTRE/utils/gss
     fi
     if ! echo $PATH | grep -q $LUSTRE/tests; then
-       export PATH=$PATH:$LUSTRE/tests
+        export PATH=$PATH:$LUSTRE/tests
     fi
+    export LST=${LST:-"$LUSTRE/../lnet/utils/lst"}
+    [ ! -f "$LST" ] && export LST=$(which lst)
     export MDSRATE=${MDSRATE:-"$LUSTRE/tests/mpi/mdsrate"}
     [ ! -f "$MDSRATE" ] && export MDSRATE=$(which mdsrate 2> /dev/null)
     if ! echo $PATH | grep -q $LUSTRE/tests/racer; then
-        export PATH=$PATH:$LUSTRE/tests/racer
+        export PATH=$LUSTRE/tests/racer:$PATH:
     fi
     if ! echo $PATH | grep -q $LUSTRE/tests/mpi; then
         export PATH=$PATH:$LUSTRE/tests/mpi
@@ -221,23 +233,64 @@ module_loaded () {
    /sbin/lsmod | grep -q $1
 }
 
+# Load a module on the system where this is running.
+#
+# Synopsis: load_module module_name [module arguments for insmod/modprobe]
+#
+# If module arguments are not given but MODOPTS_<MODULE> is set, then its value
+# will be used as the arguments.  Otherwise arguments will be obtained from
+# /etc/modprobe.conf, from /etc/modprobe.d/Lustre, or else none will be used.
+#
 load_module() {
+    local optvar
     EXT=".ko"
     module=$1
     shift
     BASE=`basename $module $EXT`
 
+    # If no module arguments were passed, get them from $MODOPTS_<MODULE>, else from
+    # modprobe.conf
+    if [ $# -eq 0 ]; then
+        # $MODOPTS_<MODULE>; we could use associative arrays, but that's not in
+        # Bash until 4.x, so we resort to eval.
+        optvar="MODOPTS_$(basename $module | tr a-z A-Z)"
+        eval set -- \$$optvar
+        if [ $# -eq 0 -a -n "$MODPROBECONF" ]; then
+            # Nothing in $MODOPTS_<MODULE>; try modprobe.conf
+            set -- $(grep "^options\\s*\<${module}\>" $MODPROBECONF)
+            # Get rid of "options $module"
+           (($# > 0)) && shift 2
+
+            # Ensure we have accept=all for lnet
+            if [ $(basename $module) = lnet ]; then
+                # OK, this is a bit wordy...
+                local arg accept_all_present=false
+                for arg in "$@"; do
+                    [ "$arg" = accept=all ] && accept_all_present=true
+                done
+                $accept_all_present || set -- "$@" accept=all
+            fi
+        fi
+    fi
+
+    [ $# -gt 0 ] && echo "${module} options: '$*'"
+
     module_loaded ${BASE} && return
 
-    if [ -f ${LUSTRE}/${module}${EXT} ]; then
-        insmod ${LUSTRE}/${module}${EXT} $@
+    # Note that insmod will ignore anything in modprobe.conf, which is why we're
+    # passing options on the command-line.
+    if [ "$BASE" == "lnet_selftest" ] && \
+            [ -f ${LUSTRE}/../lnet/selftest/${module}${EXT} ]; then
+        insmod ${LUSTRE}/../lnet/selftest/${module}${EXT}
+    elif [ -f ${LUSTRE}/${module}${EXT} ]; then
+        insmod ${LUSTRE}/${module}${EXT} "$@"
     else
         # must be testing a "make install" or "rpm" installation
         # note failed to load ptlrpc_gss is considered not fatal
         if [ "$BASE" == "ptlrpc_gss" ]; then
-            modprobe $BASE $@ 2>/dev/null || echo "gss/krb5 is not supported"
+            modprobe $BASE "$@" 2>/dev/null || echo "gss/krb5 is not supported"
         else
-            modprobe $BASE $@
+            modprobe $BASE "$@"
         fi
     fi
 }
@@ -245,10 +298,12 @@ load_module() {
 load_modules_local() {
     if [ -n "$MODPROBE" ]; then
         # use modprobe
-    return 0
+        echo "Using modprobe to load modules"
+        return 0
     fi
     if [ "$HAVE_MODULES" = true ]; then
-    # we already loaded
+        # we already loaded
+        echo "Modules already loaded"
         return 0
     fi
     HAVE_MODULES=true
@@ -257,15 +312,7 @@ load_modules_local() {
     load_module ../libcfs/libcfs/libcfs
     [ "$PTLDEBUG" ] && lctl set_param debug="$PTLDEBUG"
     [ "$SUBSYSTEM" ] && lctl set_param subsystem_debug="${SUBSYSTEM# }"
-    local MODPROBECONF=
-    [ -f /etc/modprobe.conf ] && MODPROBECONF=/etc/modprobe.conf
-    [ ! "$MODPROBECONF" -a -d /etc/modprobe.d ] && MODPROBECONF=/etc/modprobe.d/Lustre
-    [ -z "$LNETOPTS" -a "$MODPROBECONF" ] && \
-        LNETOPTS=$(awk '/^options lnet/ { print $0}' $MODPROBECONF | sed 's/^options lnet //g')
-    echo $LNETOPTS | grep -q "accept=all"  || LNETOPTS="$LNETOPTS accept=all";
-    echo "lnet options: '$LNETOPTS'"
-    # note that insmod will ignore anything in modprobe.conf
-    load_module ../lnet/lnet/lnet $LNETOPTS
+    load_module ../lnet/lnet/lnet
     LNETLND=${LNETLND:-"socklnd/ksocklnd"}
     load_module ../lnet/klnds/$LNETLND
     load_module lvfs/lvfs
@@ -338,9 +385,11 @@ unload_modules() {
 
     if $LOAD_MODULES_REMOTE ; then
         local list=$(comma_list $(remote_nodes_list))
-        echo unloading modules on $list
-        do_rpc_nodes $list $LUSTRE_RMMOD $FSTYPE
-        do_rpc_nodes $list check_mem_leak
+        if [ ! -z $list ]; then
+            echo unloading modules on $list
+            do_rpc_nodes $list $LUSTRE_RMMOD $FSTYPE
+            do_rpc_nodes $list check_mem_leak
+        fi
     fi
 
     HAVE_MODULES=false
@@ -355,7 +404,7 @@ check_gss_daemon_nodes() {
     local list=$1
     dname=$2
 
-    do_nodes --verbose $list "num=\\\$(ps -o cmd -C $dname | grep $dname | wc -l);
+    do_nodesv $list "num=\\\$(ps -o cmd -C $dname | grep $dname | wc -l);
 if [ \\\"\\\$num\\\" -ne 1 ]; then
     echo \\\$num instance of $dname;
     exit 1;
@@ -901,6 +950,8 @@ start_client_loads () {
         testnum=$((nodenum % numloads))
         start_client_load ${clients[nodenum]} ${CLIENT_LOADS[testnum]}
     done
+    # bug 22169: wait the background threads to start
+    sleep 2
 }
 
 # only for remote client 
@@ -1086,10 +1137,7 @@ wait_recovery_complete () {
     local facet=$1
 
     # Use default policy if $2 is not passed by caller.
-    #define OBD_RECOVERY_TIMEOUT (obd_timeout * 5 / 2)
-    # as we are in process of changing obd_timeout in different ways
-    # let's set MAX longer than that
-    local MAX=${2:-$(( TIMEOUT * 4 ))}
+    local MAX=${2:-$(max_recovery_time)}
 
     local var_svc=${facet}_svc
     local procfile="*.${!var_svc}.recovery_status"
@@ -1464,12 +1512,12 @@ do_node() {
 
     if [ "$myPDSH" = "rsh" ]; then
 # we need this because rsh does not return exit code of an executed command
-       local command_status="$TMP/cs"
-       rsh $HOST ":> $command_status"
-       rsh $HOST "(PATH=\$PATH:$RLUSTRE/utils:$RLUSTRE/tests:/sbin:/usr/sbin;
-                   cd $RPWD; LUSTRE=\"$RLUSTRE\" sh -c \"$@\") ||
-                   echo command failed >$command_status"
-       [ -n "$($myPDSH $HOST cat $command_status)" ] && return 1 || true
+        local command_status="$TMP/cs"
+        rsh $HOST ":> $command_status"
+        rsh $HOST "(PATH=\$PATH:$RLUSTRE/utils:$RLUSTRE/tests:/sbin:/usr/sbin;
+                    cd $RPWD; LUSTRE=\"$RLUSTRE\" sh -c \"$@\") ||
+                    echo command failed >$command_status"
+        [ -n "$($myPDSH $HOST cat $command_status)" ] && return 1 || true
         return 0
     fi
 
@@ -1486,10 +1534,25 @@ do_node() {
     return ${PIPESTATUS[0]}
 }
 
+do_nodev() {
+    do_node --verbose "$@"
+}
+
 single_local_node () {
    [ "$1" = "$HOSTNAME" ]
 }
 
+# Outputs environment variable assignments that should be passed to remote nodes
+get_env_vars() {
+    local var
+    local value
+
+    for var in ${!MODOPTS_*}; do
+        value=${!var}
+        echo "${var}=\"$value\""
+    done
+}
+
 do_nodes() {
     local verbose=false
     # do not stripe off hostname if verbose, bug 19215
@@ -1501,11 +1564,11 @@ do_nodes() {
     local rnodes=$1
     shift
 
-    if $(single_local_node $rnodes); then
+    if single_local_node $rnodes; then
         if $verbose; then
-           do_node --verbose $rnodes $@
+           do_nodev $rnodes "$@"
         else
-           do_node $rnodes $@
+           do_node $rnodes "$@"
         fi
         return $?
     fi
@@ -1522,9 +1585,9 @@ do_nodes() {
     fi
 
     if $verbose ; then
-        $myPDSH $rnodes "(PATH=\$PATH:$RLUSTRE/utils:$RLUSTRE/tests:/sbin:/usr/sbin; cd $RPWD; LUSTRE=\"$RLUSTRE\" sh -c \"$@\")"
+        $myPDSH $rnodes "(PATH=\$PATH:$RLUSTRE/utils:$RLUSTRE/tests:/sbin:/usr/sbin; cd $RPWD; LUSTRE=\"$RLUSTRE\" $(get_env_vars) sh -c \"$@\")"
     else
-        $myPDSH $rnodes "(PATH=\$PATH:$RLUSTRE/utils:$RLUSTRE/tests:/sbin:/usr/sbin; cd $RPWD; LUSTRE=\"$RLUSTRE\" sh -c \"$@\")" | sed -re "s/\w+:\s//g"
+        $myPDSH $rnodes "(PATH=\$PATH:$RLUSTRE/utils:$RLUSTRE/tests:/sbin:/usr/sbin; cd $RPWD; LUSTRE=\"$RLUSTRE\" $(get_env_vars) sh -c \"$@\")" | sed -re "s/\w+:\s//g"
     fi
     return ${PIPESTATUS[0]}
 }
@@ -1537,6 +1600,10 @@ do_facet() {
     do_node $HOST "$@"
 }
 
+do_nodesv() {
+    do_nodes --verbose "$@"
+}
+
 add() {
     local facet=$1
     shift
@@ -1593,6 +1660,10 @@ stopall() {
         rm -f $TMP/ost${num}active
     done
 
+    if ! combined_mgs_mds ; then
+        stop mgs
+    fi
+
     return 0
 }
 
@@ -1610,6 +1681,10 @@ mdsmkfsopts()
     test $nr = 1 && echo -n $MDS_MKFS_OPTS || echo -n $MDSn_MKFS_OPTS
 }
 
+combined_mgs_mds () {
+    [[ $MDSDEV1 = $MGSDEV ]] && [[ $mds1_HOST = $mgs_HOST ]]
+}
+
 formatall() {
     if [ "$IAMDIR" == "yes" ]; then
         MDS_MKFS_OPTS="$MDS_MKFS_OPTS --iam-dir"
@@ -1623,7 +1698,7 @@ formatall() {
     load_modules
     [ "$CLIENTONLY" ] && return
     echo Formatting mgs, mds, osts
-    if [[ $MDSDEV1 != $MGSDEV ]] || [[ $mds1_HOST != $mgs_HOST ]]; then
+    if ! combined_mgs_mds ; then
         add mgs $mgs_MKFS_OPTS $FSTYPE_OPT --reformat $MGSDEV || exit 10
     fi
 
@@ -1687,8 +1762,8 @@ switch_identity() {
 
 remount_client()
 {
-       zconf_umount `hostname` $1 || error "umount failed"
-       zconf_mount `hostname` $1 || error "mount failed"
+        zconf_umount `hostname` $1 || error "umount failed"
+        zconf_mount `hostname` $1 || error "mount failed"
 }
 
 writeconf_facet () {
@@ -1722,7 +1797,7 @@ setupall() {
         echo Setup mgs, mdt, osts
         echo $WRITECONF | grep -q "writeconf" && \
             writeconf_all
-        if [[ $mds1_HOST != $mgs_HOST ]] || [[ $MDSDEV1 != $MGSDEV ]]; then
+        if ! combined_mgs_mds ; then
             start mgs $MGSDEV $mgs_MOUNT_OPTS
         fi
 
@@ -1737,9 +1812,9 @@ setupall() {
                 eval mds${num}failover_HOST=$(facet_host mds$num)
             fi
 
-           if [ $IDENTITY_UPCALL != "default" ]; then
+            if [ $IDENTITY_UPCALL != "default" ]; then
                 switch_identity $num $IDENTITY_UPCALL
-           fi
+            fi
         done
         for num in `seq $OSTCOUNT`; do
             DEVNAME=$(ostdevname $num)
@@ -1768,7 +1843,7 @@ setupall() {
     [ -n "$CLIENTS" ] && zconf_mount_clients $CLIENTS $MOUNT
 
     if [ "$MOUNT_2" ]; then
-       mount_client $MOUNT2
+        mount_client $MOUNT2
         [ -n "$CLIENTS" ] && zconf_mount_clients $CLIENTS $MOUNT2
     fi
 
@@ -1788,7 +1863,7 @@ setupall() {
 }
 
 mounted_lustre_filesystems() {
-       awk '($3 ~ "lustre" && $1 ~ ":") { print $2 }' /proc/mounts
+        awk '($3 ~ "lustre" && $1 ~ ":") { print $2 }' /proc/mounts
 }
 
 init_facet_vars () {
@@ -1860,11 +1935,6 @@ osc_ensure_active () {
     [ $period -lt $timeout ] || log "$count OST are inactive after $timeout seconds, give up"
 }
 
-som_check() {
-    SOM_ENABLED=$(do_facet $SINGLEMDS "$LCTL get_param mdt.*.som" | awk -F= ' {print $2}' | head -n 1)
-    echo $SOM_ENABLED
-}
-
 init_param_vars () {
     if ! remote_ost_nodsh && ! remote_mds_nodsh; then
         export MDSVER=$(do_facet $SINGLEMDS "lctl get_param version" | cut -d. -f1,2)
@@ -1880,10 +1950,6 @@ init_param_vars () {
     osc_ensure_active $SINGLEMDS M $TIMEOUT
     osc_ensure_active client c $TIMEOUT
 
-    if [ x"$(som_check)" = x"enabled" ]; then
-        ENABLE_QUOTA=""
-        echo "disable quota temporary when SOM enabled"
-    fi
     if [ $QUOTA_AUTO -ne 0 ]; then
         if [ "$ENABLE_QUOTA" ]; then
             echo "enable quota as required"
@@ -2070,7 +2136,7 @@ cleanup_and_setup_lustre() {
         lctl set_param debug=0 || true
         cleanupall
         if [ "$ONLY" == "cleanup" ]; then
-           exit 0
+            exit 0
         fi
     fi
     check_and_setup_lustre
@@ -2211,9 +2277,9 @@ at_max_get() {
 
     # suppose that all ost-s has the same at_max set
     if [ $facet == "ost" ]; then
-       do_facet ost1 "lctl get_param -n at_max"
+        do_facet ost1 "lctl get_param -n at_max"
     else
-       do_facet $facet "lctl get_param -n at_max"
+        do_facet $facet "lctl get_param -n at_max"
     fi
 }
 
@@ -2225,15 +2291,15 @@ at_max_set() {
     for facet in $@; do
         if [ $facet == "ost" ]; then
             for i in `seq $OSTCOUNT`; do
-               do_facet ost$i "lctl set_param at_max=$at_max"
+                do_facet ost$i "lctl set_param at_max=$at_max"
 
             done
         elif [ $facet == "mds" ]; then
             for i in `seq $MDSCOUNT`; do
-               do_facet mds$i "lctl set_param at_max=$at_max"
+                do_facet mds$i "lctl set_param at_max=$at_max"
             done
         else
-           do_facet $facet "lctl set_param at_max=$at_max"
+            do_facet $facet "lctl set_param at_max=$at_max"
         fi
     done
 }
@@ -2352,10 +2418,6 @@ pgcache_empty() {
             return 1
         fi
     done
-    if [[ $MDSDEV1 != $MGSDEV ]]; then
-        stop mgs 
-    fi
-
     return 0
 }
 
@@ -2401,7 +2463,6 @@ stop_full_debug_logging() {
 
 error_noexit() {
     local TYPE=${TYPE:-"FAIL"}
-    local ERRLOG
 
     local dump=true
     # do not dump logs if $1=false
@@ -2412,28 +2473,23 @@ error_noexit() {
 
     log " ${TESTSUITE} ${TESTNAME}: @@@@@@ ${TYPE}: $@ "
 
+    # We need to dump the logs on all nodes
     if $dump; then
-        ERRLOG=$TMP/lustre_${TESTSUITE}_${TESTNAME}.$(date +%s)
-        echo "Dumping lctl log to $ERRLOG"
-        # We need to dump the logs on all nodes
-        do_nodes $(comma_list $(nodes_list)) $NODE $LCTL dk $ERRLOG
+        gather_logs $(comma_list $(nodes_list))
     fi
+
     debugrestore
     [ "$TESTSUITELOG" ] && echo "$0: ${TYPE}: $TESTNAME $@" >> $TESTSUITELOG
-    TEST_FAILED=true
+    echo "$@" > $LOGDIR/err
 }
 
 error() {
     error_noexit "$@"
-    if $FAIL_ON_ERROR; then
-        reset_fail_loc
-        exit 1
-    fi
+    exit 1
 }
 
 error_exit() {
-    error_noexit "$@"
-    exit 1
+    error "$@"
 }
 
 # use only if we are ignoring failures for this test, bugno required.
@@ -2475,7 +2531,7 @@ build_test_filter() {
     done
     for G in $GRANT_CHECK_LIST; do
         eval GCHECK_ONLY_${G}=true
-       done
+        done
 }
 
 basetest() {
@@ -2488,6 +2544,14 @@ basetest() {
 
 # print a newline if the last test was skipped
 export LAST_SKIPPED=
+#
+# Main entry into test-framework. This is called with the name and
+# description of a test. The name is used to find the function to run
+# the test using "test_$name".
+#
+# This supports a variety of methods of specifying specific test to
+# run or not run.  These need to be documented...
+#
 run_test() {
     assert_DIR
 
@@ -2496,13 +2560,13 @@ run_test() {
         testname=ONLY_$1
         if [ ${!testname}x != x ]; then
             [ "$LAST_SKIPPED" ] && echo "" && LAST_SKIPPED=
-            run_one $1 "$2"
+            run_one_logged $1 "$2"
             return $?
         fi
         testname=ONLY_$base
         if [ ${!testname}x != x ]; then
             [ "$LAST_SKIPPED" ] && echo "" && LAST_SKIPPED=
-            run_one $1 "$2"
+            run_one_logged $1 "$2"
             return $?
         fi
         LAST_SKIPPED="y"
@@ -2535,18 +2599,13 @@ run_test() {
     fi
 
     LAST_SKIPPED=
-    run_one $1 "$2"
+    run_one_logged $1 "$2"
 
     return $?
 }
 
-EQUALS="======================================================================"
 equals_msg() {
-    msg="$@"
-
-    local suffixlen=$((${#EQUALS} - ${#msg}))
-    [ $suffixlen -lt 5 ] && suffixlen=5
-    log `echo $(printf '===== %s %.*s\n' "$msg" $suffixlen $EQUALS)`
+    banner "$*"
 }
 
 log() {
@@ -2567,16 +2626,21 @@ log() {
 }
 
 trace() {
-       log "STARTING: $*"
-       strace -o $TMP/$1.strace -ttt $*
-       RC=$?
-       log "FINISHED: $*: rc $RC"
-       return 1
+        log "STARTING: $*"
+        strace -o $TMP/$1.strace -ttt $*
+        RC=$?
+        log "FINISHED: $*: rc $RC"
+        return 1
 }
 
 pass() {
-    $TEST_FAILED && echo -n "FAIL " || echo -n "PASS " 
-    echo $@
+    # Set TEST_STATUS here; will be used for logging the result
+    if [ -f $LOGDIR/err ]; then
+        TEST_STATUS="FAIL"
+    else
+        TEST_STATUS="PASS"
+    fi
+    echo $TEST_STATUS " " $@
 }
 
 check_mds() {
@@ -2591,33 +2655,81 @@ reset_fail_loc () {
     echo done.
 }
 
+
+#
+# Log a message (on all nodes) padded with "=" before and after. 
+# Also appends a timestamp and prepends the testsuite name.
+# 
+
+EQUALS="===================================================================================================="
+banner() {
+    msg="== ${TESTSUITE} $*"
+    last=${msg: -1:1}
+    [[ $last != "=" && $last != " " ]] && msg="$msg "
+    msg=$(printf '%s%.*s'  "$msg"  $((${#EQUALS} - ${#msg})) $EQUALS )
+    # always include at least == after the message
+    log "$msg== $(date +"%H:%M:%S (%s)")"
+}
+
+#
+# Run a single test function and cleanup after it.  
+#
+# This function should be run in a subshell so the test func can
+# exit() without stopping the whole script.
+#
 run_one() {
-    testnum=$1
-    message=$2
+    local testnum=$1
+    local message=$2
     tfile=f${testnum}
     export tdir=d0.${TESTSUITE}/d${base}
-
+    export TESTNAME=test_$testnum
     local SAVE_UMASK=`umask`
     umask 0022
 
-    local BEFORE=`date +%s`
-    echo
-    log "== test $testnum: $message == `date +%H:%M:%S` ($BEFORE)"
-    #check_mds
-    export TESTNAME=test_$testnum
-    TEST_FAILED=false
+    banner "test $testnum: $message"
     test_${testnum} || error "test_$testnum failed with $?"
-    #check_mds
     cd $SAVE_PWD
     reset_fail_loc
     check_grant ${testnum} || error "check_grant $testnum failed with $?"
     check_catastrophe || error "LBUG/LASSERT detected"
     ps auxww | grep -v grep | grep -q multiop && error "multiop still running"
-    pass "($((`date +%s` - $BEFORE))s)"
-    TEST_FAILED=false
     unset TESTNAME
     unset tdir
     umask $SAVE_UMASK
+    return 0
+}
+
+#
+# Wrapper around run_one to ensure:
+#  - test runs in subshell
+#  - output of test is saved to separate log file for error reporting
+#  - test result is saved to data file
+#
+run_one_logged() {
+    local BEFORE=`date +%s`
+    local TEST_ERROR
+    local name=${TESTSUITE}.test_${1}.test_log.$(hostname).log
+    local test_log=$LOGDIR/$name
+    rm -rf $LOGDIR/err
+
+    echo
+    log_sub_test_begin test_${1}
+    (run_one $1 "$2") 2>&1 | tee $test_log
+    local RC=${PIPESTATUS[0]}
+
+    [ $RC -ne 0 ] && [ ! -f $LOGDIR/err ] && \
+        echo "test_$1 returned $RC" | tee $LOGDIR/err
+
+    duration=$((`date +%s` - $BEFORE))
+    pass "(${duration}s)"
+    [ -f $LOGDIR/err ] && TEST_ERROR=$(cat $LOGDIR/err)
+    log_sub_test_end $TEST_STATUS $duration "$RC" "$TEST_ERROR"
+
+    if [ -f $LOGDIR/err ]; then
+        $FAIL_ON_ERROR && exit $RC
+    fi
+
+    return 0
 }
 
 canonical_path() {
@@ -2627,50 +2739,50 @@ canonical_path() {
 sync_clients() {
     [ -d $DIR1 ] && cd $DIR1 && sync; sleep 1; sync
     [ -d $DIR2 ] && cd $DIR2 && sync; sleep 1; sync
-       cd $SAVE_PWD
+        cd $SAVE_PWD
 }
 
 check_grant() {
     export base=`basetest $1`
     [ "$CHECK_GRANT" == "no" ] && return 0
 
-       testname=GCHECK_ONLY_${base}
+        testname=GCHECK_ONLY_${base}
         [ ${!testname}x == x ] && return 0
 
     echo -n "checking grant......"
-       cd $SAVE_PWD
-       # write some data to sync client lost_grant
-       rm -f $DIR1/${tfile}_check_grant_* 2>&1
-       for i in `seq $OSTCOUNT`; do
-               $LFS setstripe $DIR1/${tfile}_check_grant_$i -i $(($i -1)) -c 1
-               dd if=/dev/zero of=$DIR1/${tfile}_check_grant_$i bs=4k \
-                                             count=1 > /dev/null 2>&1
-       done
-       # sync all the data and make sure no pending data on server
-       sync_clients
-       
-       #get client grant and server grant
-       client_grant=0
+        cd $SAVE_PWD
+        # write some data to sync client lost_grant
+        rm -f $DIR1/${tfile}_check_grant_* 2>&1
+        for i in `seq $OSTCOUNT`; do
+                $LFS setstripe $DIR1/${tfile}_check_grant_$i -i $(($i -1)) -c 1
+                dd if=/dev/zero of=$DIR1/${tfile}_check_grant_$i bs=4k \
+                                              count=1 > /dev/null 2>&1
+        done
+        # sync all the data and make sure no pending data on server
+        sync_clients
+        
+        #get client grant and server grant
+        client_grant=0
     for d in `lctl get_param -n osc.*.cur_grant_bytes`; do
-               client_grant=$((client_grant + $d))
-       done
-       server_grant=0
-       for d in `lctl get_param -n obdfilter.*.tot_granted`; do
-               server_grant=$((server_grant + $d))
-       done
-
-       # cleanup the check_grant file
-       for i in `seq $OSTCOUNT`; do
-               rm $DIR1/${tfile}_check_grant_$i
-       done
-
-       #check whether client grant == server grant
-       if [ $client_grant != $server_grant ]; then
-               echo "failed: client:${client_grant} server: ${server_grant}"
-               return 1
-       else
-               echo "pass"
-       fi
+                client_grant=$((client_grant + $d))
+        done
+        server_grant=0
+        for d in `lctl get_param -n obdfilter.*.tot_granted`; do
+                server_grant=$((server_grant + $d))
+        done
+
+        # cleanup the check_grant file
+        for i in `seq $OSTCOUNT`; do
+                rm $DIR1/${tfile}_check_grant_$i
+        done
+
+        #check whether client grant == server grant
+        if [ $client_grant != $server_grant ]; then
+                echo "failed: client:${client_grant} server: ${server_grant}"
+                return 1
+        else
+                echo "pass"
+        fi
 }
 
 ########################
@@ -2706,6 +2818,13 @@ remote_mds_nodsh()
     remote_mds && [ "$PDSH" = "no_dsh" -o -z "$PDSH" -o -z "$mds_HOST" ]
 }
 
+require_dsh_mds()
+{
+        remote_mds_nodsh && echo "SKIP: $TESTSUITE: remote MDS with nodsh" && \
+            MSKIPPED=1 && return 1
+        return 0
+}
+
 remote_ost ()
 {
     local node
@@ -2721,6 +2840,13 @@ remote_ost_nodsh()
     remote_ost && [ "$PDSH" = "no_dsh" -o -z "$PDSH" -o -z "$ost_HOST" ]
 }
 
+require_dsh_ost()
+{
+        remote_ost_nodsh && echo "SKIP: $TESTSUITE: remote OST with nodsh" && \
+            OSKIPPED=1 && return 1
+        return 0
+}
+
 remote_mgs_nodsh()
 {
     local MGS 
@@ -2728,6 +2854,12 @@ remote_mgs_nodsh()
     remote_node $MGS && [ "$PDSH" = "no_dsh" -o -z "$PDSH" -o -z "$ost_HOST" ]
 }
 
+local_mode ()
+{
+    remote_mds_nodsh || remote_ost_nodsh || \
+        $(single_local_node $(comma_list $(nodes_list)))
+}
+
 mdts_nodes () {
     local MDSNODES
     local NODES_sort
@@ -2847,9 +2979,10 @@ mixed_mdt_devs () {
 generate_machine_file() {
     local nodes=${1//,/ }
     local machinefile=$2
-    rm -f $machinefile || error "can't rm $machinefile"
+    rm -f $machinefile
     for node in $nodes; do
-        echo $node >>$machinefile
+        echo $node >>$machinefile || \
+            { echo "can not generate machinefile $machinefile" && return 1; }
     done
 }
 
@@ -2860,6 +2993,17 @@ get_stripe () {
     rm -f $file
 }
 
+setstripe_nfsserver () {
+    local dir=$1
+
+    local nfsserver=$(awk '"'$dir'" ~ $2 && $3 ~ "nfs" && $2 != "/" \
+                { print $1 }' /proc/mounts | cut -f 1 -d : | head -1)
+
+    [ -z $nfsserver ] && echo "$dir is not nfs mounted" && return 1
+
+    do_nodev $nfsserver lfs setstripe "$@"
+}
+
 check_runas_id_ret() {
     local myRC=0
     local myRUNAS_UID=$1
@@ -2968,6 +3112,10 @@ inodes_available () {
     echo $IFree
 }
 
+mdsrate_inodes_available () {
+    echo $(($(inodes_available) - 1))
+}
+
 # reset llite stat counters
 clear_llite_stats(){
         lctl set_param -n llite.*.stats 0
@@ -3005,7 +3153,7 @@ calc_osc_kbytes () {
 # generate a stream of formatted strings (<node> <param name>=<param value>)
 save_lustre_params() {
         local s
-        do_nodes --verbose $1 "lctl get_param $2 | while read s; do echo \\\$s; done"
+        do_nodesv $1 "lctl get_param $2 | while read s; do echo \\\$s; done"
 }
 
 # restore lustre parameters from input stream, produces by save_lustre_params
@@ -3034,19 +3182,19 @@ exit \\\$rc;"
 # $2 file
 # $3 $RUNAS
 get_stripe_info() {
-       local tmp_file
+        local tmp_file
 
-       stripe_size=0
-       stripe_count=0
-       stripe_index=0
-       tmp_file=$(mktemp)
+        stripe_size=0
+        stripe_count=0
+        stripe_index=0
+        tmp_file=$(mktemp)
 
-       do_facet $1 $3 lfs getstripe -v $2 > $tmp_file
+        do_facet $1 $3 lfs getstripe -v $2 > $tmp_file
 
-       stripe_size=`awk '$1 ~ /size/ {print $2}' $tmp_file`
-       stripe_count=`awk '$1 ~ /count/ {print $2}' $tmp_file`
-       stripe_index=`awk '$1 ~ /stripe_offset/ {print $2}' $tmp_file`
-       rm -f $tmp_file
+        stripe_size=`awk '$1 ~ /size/ {print $2}' $tmp_file`
+        stripe_count=`awk '$1 ~ /count/ {print $2}' $tmp_file`
+        stripe_index=`awk '$1 ~ /stripe_offset/ {print $2}' $tmp_file`
+        rm -f $tmp_file
 }
 
 # CMD: determine mds index where directory inode presents
@@ -3209,7 +3357,6 @@ wait_osc_import_state() {
     log "${ost_facet} now in ${CONN_STATE} state"
     return 0
 }
-
 get_clientmdc_proc_path() {
     echo "${1}-mdc-*"
 }
@@ -3218,7 +3365,9 @@ do_rpc_nodes () {
     local list=$1
     shift
 
-    do_nodes --verbose $list "PATH=$RLUSTRE/tests/:$PATH sh rpc.sh $@ " 
+    # Add paths to lustre tests for 32 and 64 bit systems.
+    local RPATH="$RLUSTRE/tests:/usr/lib/lustre/tests:/usr/lib64/lustre/tests:$PATH"
+    do_nodesv $list "PATH=$RPATH sh rpc.sh $@ "
 }
 
 wait_clients_import_state () {
@@ -3364,27 +3513,30 @@ gather_logs () {
     # of writing the file to an NFS directory so it doesn't need to be copied.
     local tmp=$TMP
     local docp=true
-    [ -d "$SHARED_DIR_LOGS" ] && tmp=$SHARED_DIR_LOGS && docp=false
-
+    [ -f $LOGDIR/shared ] && docp=false
     # dump lustre logs, dmesg
-    do_nodes $list "log=$tmp/\\\$(hostname)-debug-$ts.log ;
-lctl dk \\\$log >/dev/null;
-log=$tmp/\\\$(hostname)-dmesg-$ts.log;
-dmesg > \\\$log; "
-
-    # FIXME: does it make sense to collect the logs for $ts only, but all
-    # TESTSUITE logs?
-    # rsync $TMP/*${TESTSUITE}* to gather the logs dumped by error fn
-    local logs=$TMP/'*'${TESTSUITE}'*'
-    if $docp; then
-        logs=$logs' '$tmp/'*'$ts'*'
-    fi
-    for node in ${list//,/ }; do
-        rsync -az $node:"$logs" $TMP
-    done
 
-    local archive=$TMP/${TESTSUITE}-$ts.tar.bz2
-    tar -jcf $archive $tmp/*$ts* $TMP/*${TESTSUITE}*
+    prefix="$LOGDIR/${TESTSUITE}.${TESTNAME}"
+    suffix="$ts.log"
+    echo "Dumping lctl log to ${prefix}.*.${suffix}"
+
+    if [ "$CLIENTONLY" -o "$PDSH" == "no_dsh" ]; then
+        echo "Dumping logs only on local client."
+        $LCTL dk > ${prefix}.debug_log.$(hostname).${suffix}
+        dmesg > ${prefix}.dmesg.$(hostname).${suffix}
+        return
+    fi
+
+    do_nodesv $list \
+        "$LCTL dk > ${prefix}.debug_log.\\\$(hostname).${suffix};
+         dmesg > ${prefix}.dmesg.\\\$(hostname).${suffix}"
+    if [ ! -f $LOGDIR/shared ]; then
+        do_nodes $list rsync -az "${prefix}.*.${suffix}" $HOSTNAME:$LOGDIR
+      fi
+
+    local archive=$LOGDIR/${TESTSUITE}-$ts.tar.bz2
+    tar -jcf $archive $LOGDIR/*$ts* $LOGDIR/*${TESTSUITE}*
 
     echo $archive
 }
@@ -3418,6 +3570,24 @@ do_ls () {
     return $rc
 }
 
+# target_start_and_reset_recovery_timer()
+#        service_time = at_est2timeout(service_time);
+#        service_time += 2 * (CONNECTION_SWITCH_MAX + CONNECTION_SWITCH_INC +
+#                             INITIAL_CONNECT_TIMEOUT);
+# CONNECTION_SWITCH_MAX : min(25U, max(CONNECTION_SWITCH_MIN,obd_timeout))
+#define CONNECTION_SWITCH_INC 1
+#define INITIAL_CONNECT_TIMEOUT max(CONNECTION_SWITCH_MIN,obd_timeout/20)
+#define CONNECTION_SWITCH_MIN 5U
+
+max_recovery_time () {
+    local init_connect_timeout=$(( TIMEOUT / 20 ))
+    [[ $init_connect_timeout > 5 ]] || init_connect_timeout=5 
+
+    local service_time=$(( $(at_max_get client) + $(( 2 * $(( 25 + 1  + init_connect_timeout)) )) ))
+
+    echo $service_time 
+}
+
 get_clients_mount_count () {
     local clients=${CLIENTS:-`hostname`}
 
@@ -3439,7 +3609,7 @@ combination()
         R=0
     else
         N=$((N + 1))
-        while [ $N -le $M ]; do
+        while [ $N -lt $M ]; do
             R=$((R * N))
             N=$((N + 1))
         done
@@ -3650,6 +3820,7 @@ wait_flavor()
             return 0
         else
             echo "found $res $flavor connections of $dir, not ready ($expect)"
+            return 0
             sleep 4
         fi
     done
@@ -3712,3 +3883,72 @@ set_flavor_all()
 }
 
 
+check_logdir() {
+    local dir=$1
+    # Checking for shared logdir
+    if [ ! -d $dir ]; then
+        # Not found. Create local logdir
+        mkdir -p $dir
+    else
+        touch $dir/node.$(hostname).yml
+    fi
+    return 0
+}
+
+check_write_access() {
+    local dir=$1
+    for node in $(nodes_list); do
+        if [ ! -f "$dir/node.${node}.yml" ]; then
+            # Logdir not accessible/writable from this node.
+            return 1
+        fi
+    done
+    return 0
+}
+
+init_logging() {
+    if [[ -n $YAML_LOG ]]; then
+        return
+    fi
+    export YAML_LOG=${LOGDIR}/results.yml
+    mkdir -p $LOGDIR
+    init_clients_lists
+
+    do_rpc_nodes $(comma_list $(nodes_list)) check_logdir $LOGDIR
+    if check_write_access $LOGDIR; then
+        touch $LOGDIR/shared
+        echo "Logging to shared log directory: $LOGDIR"
+    else
+        echo "Logging to local directory: $LOGDIR"
+    fi
+
+    yml_nodes_file $LOGDIR
+    yml_results_file >> $YAML_LOG
+}
+
+log_test() {
+    yml_log_test $1 >> $YAML_LOG
+}
+
+log_sub_test_begin() {
+    yml_log_sub_test_begin $@ >> $YAML_LOG
+}
+
+log_sub_test_end() {
+    yml_log_sub_test_end $@ >> $YAML_LOG
+}
+
+run_llverdev()
+{
+        local dev=$1
+        local devname=$(basename $1)
+        local size=$(grep "$devname"$ /proc/partitions | awk '{print $3}')
+        size=$(($size / 1024 / 1024)) # Gb
+
+        local partial_arg=""
+        # Run in partial (fast) mode if the size
+        # of a partition > 10 GB
+        [ $size -gt 10 ] && partial_arg="-p"
+
+        llverdev --force $partial_arg $dev
+}