shellfu-bash-jat/src/jat.sh.skel

#!/bin/bash

shellfu import pretty
shellfu import isa
shellfu import termcolors

#
# Just A[nother] Test assert and logging library
#
#
# COMMON ARGUMENTS
# ================
#
# Assert functions share following parameters:
#
#  *  `-b BEID`   Behavior Evidence ID; is a Simple Name (see STRINGS)
#     associated with a particular behavior.  If provided, BEID is merely
#     included within the log, see BEHAVIOR EVIDENCE ID section for more
#     details.
#
#  *  `-c CASEID`   Case ID; together with $JAT__TEST_ID can be used to
#     uniquely identify a particular test case, with granularity up to
#     single assert.  CASEID set here is joined with any CASEIDs set
#     by active phase.
#
#  *  `-h HINT`   Human-readable description used to describe meaning of
#     the assertion to reader.  Note that HINT should be worded in such
#     way that it makes claim about the reality that matches expectation.
#     That is, to reader of the log, a passing assert tells true, but
#     a failing assert "lies".
#
# Phase start functions share following parameters:
#
#  *  `-C DIR`  Change to directory DIR for duration of the phase.
#
#  *  `-c CASEID`  Inherit CASEID as Case ID to all asserts in this
#     phase.  Individual asserts can extend the final case id for
#     extra granularity and profit.
#
#
# STRINGS
# =======
#
# Many strings, when passed to jat functions, are internally used
# as paths, prefixes or identifiers.  For this reason, they may be
# restricted to contain only "safe" chars.  Following classes are
# defined:
#
#  *  *simple word* - must begin with letter or underscore; second
#     and further characters may be letter, digit or underscore.
#

#
# Path to result directory
#
JAT__DIR=${JAT__DIR:-/var/tmp/jat}

#
# Path to result log
#
# If unset, another identical log is *still* created under a unique
# subdirectory of $JAT__DIR.  Set this if you want to have log at
# a predictable path.  This can be useful  eg. if you want to send
# log into a named pipe.
#
JAT__YLOG=${JAT__YLOG:-}

#
# Behavior Evidence ID namespace
#
# All BEIDs will be prefixed by this namespace qualifier,
# and meaning of them must be defined within that namespace.
#
JAT__BEID_NS=${JAT__BEID_NS:-_jat_anon_beid_ns_}

#
# Test name
#
JAT__TEST_ID=${JAT__TEST_ID:-_jat_anon_test_}

#
# Test version
#
JAT__TEST_VERSION=${JAT__TEST_VERSION:-_jat_no_test_version_}

#
# Path to main logfile
#
__JAT__SDIR=

#
# Colored words for `jat__show_*` functions
#
__JAT__SWORD_ASSERT=${TERMCOLORS_YELLOW}assert${TERMCOLORS_NONE}
__JAT__SWORD_END=${TERMCOLORS_LBLACK}END${TERMCOLORS_NONE}
__JAT__SWORD_FAIL=${TERMCOLORS_RED}FAIL${TERMCOLORS_NONE}
__JAT__SWORD_FINALIZE=${TERMCOLORS_LBLACK}FINALIZE${TERMCOLORS_NONE}
__JAT__SWORD_PASS=${TERMCOLORS_GREEN}PASS${TERMCOLORS_NONE}
__JAT__SWORD_PHASE=${TERMCOLORS_YELLOW}phase${TERMCOLORS_NONE}
__JAT__SWORD_RELOAD=${TERMCOLORS_LBLUE}RELOAD${TERMCOLORS_NONE}
__JAT__SWORD_SESSION=${TERMCOLORS_YELLOW}session${TERMCOLORS_NONE}
__JAT__SWORD_START=${TERMCOLORS_LBLACK}START${TERMCOLORS_NONE}
__JAT__SWORD_TERROR=${TERMCOLORS_RED}ERROR${TERMCOLORS_NONE}
__JAT__SWORD_TEST=${TERMCOLORS_YELLOW}test${TERMCOLORS_NONE}
__JAT__SWORD_TINFO=${TERMCOLORS_LBLACK}INFO${TERMCOLORS_NONE}
__JAT__SWORD_TWARNING=${TERMCOLORS_RED}WARNING${TERMCOLORS_NONE}


#
# Make result log deterministic?
#
# Determines whether result should be made deterministic.  Currently
# this means that instead of wall clock time, timestamps will be simply
# ordinal stamps like `time-1`, `time-2`...
#
# This makes test log deterministic, enabling comparison of multiple
# runs against each other or against fixed oracle.  The disadvantage
# is that you can't assess performance data from the log.
#
__JAT__DETERMINISTIC=false

#
# Log format version
#
__JAT__LOG_FMT='jat/0.0'

#
# Self version (in variable to enable overriding in unit tests)
#
__JAT__SELF_VERSION=__MKIT_PROJ_VERSION__

jat__cmd() {
    #
    # Assert that command $@ exits with zero (or other)
    #
    # Usage:
    #
    #     jat__cmd [-o R_OUT] [-e R_ERR] [-s R_ESF] [-S ES_EXPR] [--] CMD [ARG]..
    #
    # Run CMD with all ARGs and if exit status is zero, announce assertion
    # success (ASSERT.PASS), otherwise announce assertion failure (ASSERT.FAIL).
    #
    # Exit status expectation can be changed from zero to ES_EXPR, which
    # must be in form of comma-separated list of integer values or ranges
    # thereof.  E, g. expression '0,10-20' would be a valid expression,
    # matching 0, 11, 20, but not 2 or 21.
    #
    # If R_ESF is passed, it will be treated as path to file where exit status
    # of CODE is written.  This is recommended over consulting $?, since the
    # latter is not reliable; see below.
    #
    # If path R_OUT or R_ERR are provided, standard output and standard
    # error are saved to respective files.
    #
    # See COMMON ARGUMENTS section for common assert options.
    #
    # Exit status of the this function normally will, but IS NOT GUARRANTEED TO
    # correspond to the exit status of the CODE. For example, if the function
    # call is incomplete, the exit status will be 2.
    #
    local __jat__cmd=()
    local __jat__r_es
    local __jat__o_es=0
    local __jat__hint
    local __jat__beids=()
    local __jat__caseid
    local __jat__etype=MESSAGE.ERROR
    local __jat__r_out
    local __jat__r_err
    local __jat__r_esf
    #
    # NOTE: names need to be qualified because they might interfere
    #       with the actual execution of the assert command.
    #
    while true; do case $1 in
        -b) __jat__beids+=("$2"); shift 2 || { __jat__usage "missing BEID"; return 2; } ;;
        -c) __jat__caseid="$2"; shift 2 || { __jat__usage "missing CASEID"; return 2; } ;;
        -h) __jat__hint=$2; shift 2 || { __jat__usage "missing HINT"; return 2; } ;;
        -e) __jat__r_err=$2; shift 2 || { __jat__usage "missing R_ERR"; return 2; } ;;
        -o) __jat__r_out=$2; shift 2 || { __jat__usage "missing R_OUT"; return 2; } ;;
        -s) __jat__r_esf=$2; shift 2 || { __jat__usage "missing R_ESF"; return 2; } ;;
        -S) __jat__o_es=$2; shift 2 || { __jat__usage "missing ES_EXPR"; return 2; } ;;
        --) shift; break ;;
        *) break ;;
    esac done
    __jat__cmd=("$@")
    test -n "${__jat__cmd[*]}" || { __jat__usage "no CMD?"; return 2; }
    test -n "$__jat__hint" || __jat__hint="${__jat__cmd[*]}"
    debug -v __jat__cmd __jat__o_es __jat__hint __jat__beids
    jat__log_info "CMD: ${__jat__cmd[*]}"
    case ${#__jat__r_out}:${#__jat__r_err} in
        0:0) "${__jat__cmd[@]}" ;;
        0:*) "${__jat__cmd[@]}" 2>"$__jat__r_err" ;;
        *:0) "${__jat__cmd[@]}" >"$__jat__r_out" ;;
        *:*) "${__jat__cmd[@]}" >"$__jat__r_out" 2>"$__jat__r_err" ;;
    esac; __jat__r_es=$?
    debug -v __jat__r_es __jat__r_esf
    if test -n "$__jat__r_esf"; then
        echo $__jat__r_es > "$__jat__r_esf" \
         || jat__log_error "error writing R_ESF file: $__jat__r_esf"
    fi
    if __jat__es_match "$__jat__o_es" "$__jat__r_es"; then
        __jat__etype=ASSERT.PASS
    else
        __jat__etype=ASSERT.FAIL
    fi
    __jat__assert $__jat__etype "$__jat__hint" "$__jat__caseid" "${__jat__beids[@]}" \
        "t.cmd=${__jat__cmd[*]}" "o.es_expr=$__jat__o_es" "r.es=$__jat__r_es"
    return "$__jat__r_es"
}

jat__cmp() {
    #
    # Assert comparison of $1 and $3 using operator $2
    #
    # Usage:
    #
    #     jat__cmp [assert-options] RVAL OP OVAL
    #
    # Compare RVAL (result value) to OVAL (oracle value) and announce
    # assertion success (ASSERT.PASS) or assertion failure (ASSERT.FAIL).
    #
    # OP can be any of `eq`, `ne`, `lt`, `gt`, `le`, `ge` for numeric values,
    # `==` and `re` for string values.  In case of `re`, OVAL is expected to
    # be basic regular expression and is matched against whole string (ie.
    # anchors `^` and `$` are included automatically.
    #
    # Note that in most cases using jat__cmd() with `test` or `grep` commands
    # is all you need.
    #
    # See COMMON ARGUMENTS section for common assert options.
    #
    local RVal      # "result" value
    local Op        # operator
    local OVal      # "oracle" value
    local hint      # log hint
    local caseid    # case id
    local beids=()  # Behavior Evidence IDs
    local cmpes     # comparison exit status
    while true; do case $1 in
        -b) beids+=("$2"); shift 2 || { __jat__usage "missing BEID"; return 2; } ;;
        -c) caseid="$2"; shift 2 || { __jat__usage "missing CASEID"; return 2; } ;;
        -h) hint=$2; shift 2 || { __jat__usage "missing HINT"; return 2; } ;;
        *) break ;;
    esac done
    RVal=$1; Op=$2; OVal=$3
    test -n "$RVal" || { __jat__usage "no RVAL?"; return 2; }
    test -n "$Op" || { __jat__usage "no OP?"; return 2; }
    test -n "$OVal" || { __jat__usage "no OVAL?"; return 2; }
    test -n "$hint" || hint="$RVal $Op $OVal"
    debug -v RVal Op OVal hint beids
    __jat__cmp_match; cmpes=$?
    case $cmpes in
        0)
            __jat__assert ASSERT.PASS "$hint" "$caseid" "${beids[@]}" \
                "r.val=$RVal" "t.op=$Op" "o.val=$OVal"
            ;;
        1)
            __jat__assert ASSERT.FAIL "$hint" "$caseid" "${beids[@]}" \
                "r.val=$RVal" "t.op=$Op" "o.val=$OVal"
            ;;
        *)
            __jat__usage "bad syntax: $RVal $Op $OVal"
            return 2
            ;;
    esac
}

jat__die() {
    #
    # Log error $1 and exit this script abruptly
    #
    local msg
    local msgs=()
    for msg in "$@"; do
        msgs+=("fatal: $msg")
    done
    jat__log_error "${msgs[@]}"
    jat__sfinish
    die "${msgs[@]}"
}

jat__eval() {
    #
    # Assert that code $1 exits with zero (or other)
    #
    # Usage:
    #
    #     jat__eval [assert-options] [-s R_ESF] [-S ES_EXPR] [--] CODE
    #
    # Run CODE using eval builtin and if exit status is zero, announce assertion
    # success (ASSERT.PASS), otherwise announce assertion failure (ASSERT.FAIL).
    #
    # Exit status expectation can be changed from zero to ES_EXPR, which
    # must be in form of comma-separated list of integer values or ranges
    # thereof.  E, g. expression '0,10-20' would be a valid expression,
    # matching 0, 11, 20, but not 2 or 21.
    #
    # If R_ESF is passed, it will be treated as path to file where exit status
    # of CODE is written.  This is recommended over consulting $?, since the
    # latter is not reliable; see below.
    #
    # This is similar to jat__cmd(), except that code is checked against syntax
    # errors and user is given full control over redirections.
    #
    # See COMMON ARGUMENTS section for common assert options.
    #
    # Exit status of the this function normally will, but IS NOT GUARRANTEED TO
    # correspond to the exit status of the CODE. For example, if the function
    # call is incomplete, the exit status will be 2.  If there is syntax error
    # in CODE, the exit status will be 3.
    #
    local __jat__caseid
    local __jat__code=""
    local __jat__r_es
    local __jat__r_esf
    local __jat__o_es=0
    local __jat__hint
    local __jat__beids=()
    local __jat__etype=MESSAGE.ERROR
    #
    # NOTE: names need to be qualified because they might interfere
    #       with the actual execution of the assert command.
    #
    while true; do case $1 in
        -b) __jat__beids+=("$2"); shift 2 || { __jat__usage "missing BEID"; return 2; } ;;
        -c) __jat__caseid="$2"; shift 2 || { __jat__usage "missing CASEID"; return 2; } ;;
        -h) __jat__hint=$2; shift 2 || { __jat__usage "missing HINT"; return 2; } ;;
        -s) __jat__r_esf=$2; shift 2 || { __jat__usage "missing R_ESF"; return 2; } ;;
        -S) __jat__o_es=$2; shift 2 || { __jat__usage "missing ES_EXPR"; return 2; } ;;
        --) shift; break ;;
        *) break ;;
    esac done
    __jat__code=$1
    test -n "$__jat__code" || { __jat__usage "no CODE?"; return 2; }
    test -n "$2" &&  { __jat__usage "extra args!: $*"; return 2; }
    test -n "$__jat__hint" || __jat__hint="$__jat__code"
    debug -v __jat__code __jat__o_es __jat__hint __jat__beids
    bash -n <<<"$__jat__code" || {
        jat__log_error "syntax error in test code: $__jat__code"
        return 3
    }
    jat__log_info "CODE: $__jat__code"
    eval "$__jat__code"; __jat__r_es=$?
    if test -n "$__jat__r_esf"; then
        echo $__jat__r_es > "$__jat__r_esf" \
         || jat__log_error "error writing R_ESF file: $__jat__r_esf"
    fi
    debug -v __jat__r_es
    if __jat__es_match "$__jat__o_es" "$__jat__r_es"; then
        __jat__etype=ASSERT.PASS
    else
        __jat__etype=ASSERT.FAIL
    fi
    __jat__assert $__jat__etype "$__jat__hint" "$__jat__caseid" "${__jat__beids[@]}" \
        "t.code=$__jat__code" "o.es_expr=$__jat__o_es" "r.es=$__jat__r_es"
    return "$__jat__r_es"
}

jat__fail() {
    #
    # Assert test failure
    #
    # Usage:
    #
    #     jat__fail [assert-options]
    #
    # Simply log event that an assert has failed.  Use other assert functions
    # if you can, since they probably provide more useful information to log
    # reader.
    #
    # See COMMON ARGUMENTS section for common assert options.
    #
    local hint      # log hint
    local caseid    # case ID
    while true; do case $1 in
        -c) caseid="$2"; shift 2 || { __jat__usage "missing CASEID"; return 2; } ;;
        -h) hint=$2; shift 2 || { __jat__usage "missing HINT"; return 2; } ;;
        *) break ;;
    esac done
    test -n "$1" && { __jat__usage "extra arguments: $*"; return 2; }
    debug -v hint beids
    __jat__assert ASSERT.FAIL "$hint" "$caseid" "${beids[@]}"
}

jat__filebackup() {
    #
    # Back up file $1
    #
    # Usage:
    #
    #     jat__filebackup [-n NS] [-c] [--] PATH
    #
    # Back up PATH aside to be able to restore it later using
    # jat__filerestore().
    #
    # Provide `-c` switch to ensure that path is removed before restoring.
    # If NS is given, it must be "simple word" (see STRINGS section).
    #
    local path
    local abspath
    local ns=_jat_anon_backupns_
    local store
    local dest
    local clean=false
    local pdig
    local nshint
    while true; do case $1 in
        --) shift; break ;;
        -c|--clean)
            clean=true
            shift ;;
        -n|--namespace)
            ns=$2; nshint="(NS=$ns) "
            shift 2 || { __jat__usage "no NS?"; return 2; }
            ;;
        -*) __jat__usage "unknown argument: $1"; return 2 ;;
        *) break ;;
    esac done
    path=$1
    test -n "$path" || { __jat__usage "no PATH?"; return 2; }
    isa__name "$ns" || { __jat__usage "NS must be simple word"; return 2; }
    abspath=$(readlink -e "$path") || {
        jat__log_error "no such file: $1"
        return 3
    }
    pdig=$(md5sum <<<"$abspath" | cut -d' ' -f1)
    __jat__sd_keya "backup/$ns/rainbow" "$pdig $abspath"
    $clean && __jat__sd_keya "backup/$ns/clean" "$abspath"
    store=$(__jat__sd_path "backup/$ns/store")
    mkdir -p "$store"
    dest="$store/$pdig"
    test -e "$store/$pdig" && {
        jat__log_error "already backed up, giving up: $nshint$path"
        return 2
    }
    cp -ar "$abspath" "$store/$pdig" || {
        jat__log_error "failed to create backup: $abspath"
        return 3
    }
    jat__log_info "backed up: $nshint$path"
    debug -c tree "$(__jat__sd_path backup)"
}

jat__filerestore() {
    #
    # Restore paths stored by jat__filebackup()
    #
    # Usage:
    #
    #     jat__filerestore [-n NS]
    #
    # Restore all paths backed up using jat__filebackup().  Paths
    # are restored in opposite order than backed up.
    #
    local abspath
    local ns=_jat_anon_backupns_
    local store
    local pdig
    local nshint
    local rainbow
    local cleanlog
    while true; do case $1 in
        -n|--namespace)
            ns=$2; nshint="(NS=$ns) "
            shift 2 || { __jat__usage "no NS?"; return 2; }
            ;;
        "") break ;;
        *) __jat__usage "unknown argument: $1"; return 2 ;;
    esac done
    isa__name "$ns" || { __jat__usage "NS must be simple word"; return 2; }
    test -d "$__JAT__SDIR/internal/backup/$ns" || {
        jat__log_error "unknown backup namespace: $ns"
        return 3
    }
    rainbow=$(__jat__sd_path "backup/$ns/rainbow")
    cleanlog=$(__jat__sd_path "backup/$ns/clean")
    store=$(__jat__sd_path "backup/$ns/store")
    while read -r pdig abspath; do
        debug -v pdig abspath
        grep -qxF "$abspath" "$cleanlog" 2>/dev/null && {
            rm -rf "$abspath" || {
                jat__log_error "failed to pre-clean original path: $abspath"
                return 3
            }
        }
        debug -c ls -l "$store"
        cp -Tar "$store/$pdig" "$abspath" || {
            jat__log_error "failed to restore backup: $nshint$abspath"
            return 3
        }
        jat__log_info "restored: $nshint$abspath"
        :
    done <"$rainbow"
}

jat__sfinish() {
    #
    # Finalize session
    #
    # Log event to announce that log is finalized and remove test
    # session.
    #
    # This is necessary because in order to support persistent multi
    # PID tests (ie, re-booting within test), jat__sinit() will reload
    # leftover session and whole log will be merged.
    #
    local fileas    # session id for filing in 'finished' folder
    local es        # final exit status
    test -d "$JAT__DIR/session" || {
        __jat__show_error "no active session: no $JAT__DIR/session"
        return 2
    }
    es=$(__jat__final_es)
    __jat__show_sfinish
    __jat__log_event SESSION.END "finishing session"
    __jat__writelog <<<"finalized: true"
    __jat__writelog <<<"end: $(__jat__newstamp)"
    fileas=$(__jat__sd_keyr fileas)
    mkdir -p "$JAT__DIR/finished"
    mv "$JAT__DIR/session" "$JAT__DIR/finished/$fileas"
    rm -f "$JAT__DIR/last"
    ln -s "finished/$fileas" "$JAT__DIR/last"
    return "$es"
}

jat__log_error() {
    #
    # Log internal error unrelated to SUT
    #
    local line
    local msg
    local head=true
    for line in "$@"; do
        __jat__show_terror "$line"
        $head || msg+=$'\n'; head=false
        msg+="$line"
    done
    echo "MESSAGE.ERROR" >> "$(__jat__sd_path "llog")"
    echo "MESSAGE.ERROR" >> "$(__jat__sd_path "P.llog")"
    __jat__log_event MESSAGE.ERROR "$msg"
}

jat__log_info() {
    #
    # Log internal info unrelated to SUT
    #
    local line
    local msg
    local head=true
    for line in "$@"; do
        __jat__show_tinfo "$line"
        $head || msg+=$'\n'; head=false
        msg+="$line"
    done
    echo "MESSAGE.INFO" >> "$(__jat__sd_path "llog")"
    echo "MESSAGE.INFO" >> "$(__jat__sd_path "P.llog")"
    __jat__log_event MESSAGE.INFO "$msg"
}

jat__log_warning() {
    #
    # Log internal error unrelated to SUT
    #
    local line
    local msg
    local head=true
    for line in "$@"; do
        __jat__show_twarning "$line"
        $head || msg+=$'\n'; head=false
        msg+="$line"
    done
    echo "MESSAGE.WARNING" >> "$(__jat__sd_path "llog")"
    echo "MESSAGE.WARNING" >> "$(__jat__sd_path "P.llog")"
    __jat__log_event MESSAGE.WARNING "$msg"
}

jat__pass() {
    #
    # Assert test pass
    #
    # Usage:
    #
    #     jat__pass [assert-options]
    #
    # Simply log event that an assert has passed.  Use other assert functions
    # if you can, since they probably provide more useful information to log
    # reader.
    #
    # See COMMON ARGUMENTS section for common assert options.
    #
    local hint      # log hint
    local beids=()  # Behavior Evidence IDs
    local caseid    # case ID
    while true; do case $1 in
        -b) beids+=("$2"); shift 2 || { __jat__usage "missing BEID"; return 2; } ;;
        -c) caseid="$2"; shift 2 || { __jat__usage "missing CASEID"; return 2; } ;;
        -h) hint=$2; shift 2 || { __jat__usage "missing HINT"; return 2; } ;;
        *) break ;;
    esac done
    test -n "$1" && { __jat__usage "extra arguments: $*"; return 2; }
    debug -v hint beids
    __jat__assert ASSERT.PASS "$hint" "$caseid" "${beids[@]}"
}

jat__promise_asserts() {
    #
    # Promise number of asserts will be $1
    #
    local num=$1
    test -n "$num" || {
        __jat__usage "no NUM?"
        return 2
    }
    __jat__log_event TEST.PROMISE "assert number: $num" "" \
        "num=$num"
}

jat__sinit() {
    #
    # Initialize session
    #
    # Load active session if found; otherwise initialize new one.
    #
    local reload=false
    local old_test_id
    local old_test_version
    local sessid
    mkdir -p "$JAT__DIR" \
     || die "could not initialize JAT__DIR: $JAT__DIR"
    __JAT__SDIR=$JAT__DIR/session
    test -d "$__JAT__SDIR" && reload=true
    mkdir -p "$__JAT__SDIR"
    __jat__sd_keyw fileas "session-$(date +%s-%N)"
    export __JAT__SDIR
    export JAT__YLOG
    debug -v reload __JAT__SDIR
    if $reload; then
        sessid=$(__jat__sd_keyr sessid)
        old_test_id=$(__jat__sd_keyr test_id)
        old_test_version=$(__jat__sd_keyr test_version)
        test "$old_test_id" == "$JAT__TEST_ID" || {
            warn -v JAT__TEST_ID old_test_id
            die "cannot reload session of different test"
        }
        test "$old_test_version" == "$JAT__TEST_VERSION" || {
            warn -v JAT__TEST_VERSION old_test_version
            die "cannot reload session of different test version"
        }
        __jat__log_event SESSION.RELOAD "reloaded session" "" \
            "JAT__LOG_FMT=$__JAT__LOG_FMT" \
            "JAT__VERSION=$__JAT__SELF_VERSION"
        __jat__show_sinitr
    else
        sessid=$(__jat__newsid)
        debug -v __JAT__SDIR JAT__YLOG
        {
            echo "---"
            echo "format: $__JAT__LOG_FMT"
            echo "jat_version: $__JAT__SELF_VERSION"
            echo "test:"
            echo "    id: $JAT__TEST_ID"
            echo "    version: $JAT__TEST_VERSION"
            echo "start: $(__jat__newstamp)"
            echo "id: $sessid"
            echo "events:"
        } | __jat__writelog
        __jat__sd_keyw sessid "$sessid"
        __jat__sd_keyw test_id "$JAT__TEST_ID"
        __jat__sd_keyw test_version "$JAT__TEST_VERSION"
        __jat__pdummy
        __jat__log_event SESSION.START "started new session"
        __jat__show_sinitn
    fi
}

jat__stat() {
    #
    # Print session statistic $1
    #
    # Usage:
    #    jat__stat sasrtc      # session assert count
    #    jat__stat spassc      # session pass count
    #    jat__stat sfailc      # session fail count
    #    jat__stat pasrtc      # phase assert count
    #    jat__stat ppassc      # phase pass count
    #    jat__stat pfailc      # phase fail count
    #    jat__stat swarc       # session warning count
    #    jat__stat pwarc       # phase warning count
    #    jat__stat serrc       # session error count
    #    jat__stat perrc       # phase error count
    #
    # Print statistics about session state.
    #
    local which=$1
    case $which in
        swarc)  grep -cxF MESSAGE.WARNING "$(__jat__sd_path "llog")" ;;
        pwarc)  grep -cxF MESSAGE.WARNING "$(__jat__sd_path "P.llog")" ;;
        serrc)  grep -cxF MESSAGE.ERROR "$(__jat__sd_path "llog")" ;;
        perrc)  grep -cxF MESSAGE.ERROR "$(__jat__sd_path "P.llog")" ;;
        sfailc) grep -cxF ASSERT.FAIL "$(__jat__sd_path "vlog")" ;;
        pfailc) grep -cxF ASSERT.FAIL "$(__jat__sd_path "P.vlog")" ;;
        ppassc) grep -cxF ASSERT.PASS "$(__jat__sd_path "P.vlog")" ;;
        spassc) grep -cxF ASSERT.PASS "$(__jat__sd_path "vlog")" ;;
        pasrtc) grep -cx 'ASSERT.PASS\|ASSERT.FAIL' "$(__jat__sd_path "P.vlog")" ;;
        sasrtc) grep -cx 'ASSERT.PASS\|ASSERT.FAIL' "$(__jat__sd_path "vlog")" ;;
        *) __jat__usage "invalid statistic field: $which"
           return 2 ;;
    esac
}

jat__pend() {
    #
    # End active phase
    #
    local oldpdir
    local oldpwd
    oldpdir=$(__jat__sd_keyR P.pdir)
    oldpwd=$(__jat__sd_keyR P.PWD)
    test -n "$oldpdir" && {
        jat__log_info "changing back from phase dir: $oldpdir"
        popd >/dev/null \
         || jat__die "failed to go back from phase dir: $oldpdir to $oldpwd"
    }
    __jat__show_pend
    __jat__pdummy
    __jat__log_event PHASE.END
}

jat__pstartd() {
    #
    # Start diagnostic phase named $1
    #
    # See COMMON ARGUMENTS section of this manual.
    #
    __jat__pstart -t diag "$@"
}

jat__pstartc() {
    #
    # Start cleanup phase named $1
    #
    # See COMMON ARGUMENTS section of this manual.
    #
    __jat__pstart -t cleanup "$@"
}

jat__pstarts() {
    #
    # Start setup phase named $1
    #
    # See COMMON ARGUMENTS section of this manual.
    #
    __jat__pstart -t setup "$@"
}

jat__pstartt() {
    #
    # Start test phase named $1
    #
    # See COMMON ARGUMENTS section of this manual.
    #
    __jat__pstart -t test "$@"
}

jat__submit() {
    #
    # Submit file $1 as part of test result
    #
    # Usage:
    #
    #     jat__submit PATH [ALTNAME]
    #
    # Last element of PATH is used as result name, unless alternative
    # name ALTNAME is given, in which case it's used instead.
    #
    local path=$1
    local altname=$2
    local dest=$__JAT__SDIR/results
    local nhint
    test -n "$path" || {
        __jat__usage "no SRC?"
        return 2
    }
    mkdir -p "$dest" || {
        jat__log_error "cannot write to result storage: $dest"
        return 3
    }
    test -n "$altname" && {
        dest="$dest/$altname"
        nhint=" as $altname"
        mkdir -p "$(dirname "$dest")"   # needed if altname has slashes
    }
    jat__log_info "submitting result: $path$nhint"
    cp -ar "$path" "$dest"
}

__jat__assert() {
    #
    # Make assert event
    #
    # Use this function to create own asserts
    #
    case $1 in
        ASSERT.PASS)   __jat__show_pass "$2" ;;
        ASSERT.FAIL)   __jat__show_fail "$2" ;;
    esac
    __jat__log_event "$@"
}

__jat__bumpid() {
    #
    # Create and/or bump ID named $1
    #
    # Print next ID from series named $1.  Series starts
    # with 1, so on firts call, value of ID is 1, then 2.
    # etc.
    #
    # Isession is not initialized, ID value will be 0 and
    # return status will be 3.
    #
    local name=$1   # name of id
    local cache     # ordinal cache
    local ord       # ordinal
    if test -n "$__JAT__SDIR"; then
        cache=$(__jat__sd_path "series/$name")
    else
        echo 0; return 3
    fi
    if test -f "$cache"; then
        ord=$(<"$cache")
        ((ord++))
    else
        ord=1
    fi
    echo $ord >"$cache"
    echo "$name-$ord"
}

__jat__cmp_match() {
    #
    # True if $RVal matches $OVal by $Op
    #
    case $Op in
        eq|ne|lt|gt|le|ge) test "$RVal" -"$Op" "$OVal" ;;
        ==)                test "$RVal" == "$OVal" ;;
        re)                grep -qx "$OVal" <<< "$RVal" ;;
        *)  return 2 ;;
    esac
}

__jat__es_match() {
    #
    # True if exit status $1 matches expression $EsExpr
    #
    local expr=$1
    local es=$2
    local part
    for part in ${expr//,/ }; do
        test -n "$part" || continue
        #FIXME: a rather funny implementation (works, though...)
        eval "echo {${part/-/..}}" | grep -qwF "$es" && return 0
    done
    return 1
}

__jat__final_es() {
    #
    # Print final exit status
    #
    # Roughly follows TFKit's semantic; unoffical link:
    #
    #     https://github.com/AloisMahdal/shellfu/tree/master/utils/tfkit/doc
    #
    test "$(jat__stat serrc)"  -gt 0 && echo 4 && return
    test "$(jat__stat swarc)"  -gt 0 && echo 3 && return
    test "$(jat__stat sfailc)" -gt 0 && echo 1 && return
    echo 0
}

__jat__log_event() {
    #
    # Log event to YAML log via __jat__writelog()
    #
    # Usage:
    #
    #     __jat__log_event SESSION.START|SESSION.RELOAD|SESSION.END
    #     __jat__log_event PHASE.END
    #     __jat__log_event PHASE.START ID TYPE NAME [K=V]
    #     __jat__log_event ASSERT.PASS|ASSERT.FAIL [-h HINT] [-c CASEID] [-b BEID..] [-d K=V..]
    #     __jat__log_event MESSAGE.INFO|MESSAGE.WARNING|MESSAGE.ERROR MSG [K=V]
    #
    local EType=$1; shift
    local msg
    local meatfn
    local beids=()
    local data=()
    local origin=${FUNCNAME[1]}
    local pcaseid
    local CaseIdBase=$JAT__TEST_ID
    pcaseid=$(__jat__sd_keyR P.pcaseid)
    test -n "$pcaseid" && CaseIdBase+=":$pcaseid"
    case $EType in
        ASSERT.PASS|ASSERT.FAIL) : ;;
        MESSAGE.INFO|MESSAGE.ERROR|MESSAGE.WARNING) : ;;
        PHASE.START|PHASE.END) : ;;
        SESSION.START|SESSION.RELOAD|SESSION.END) : ;;
        *)  __jat__usage "bad ETYPE: $EType"
            return 2 ;;
    esac
    case $EType:$origin in
        PHASE.END:jat__pend)                meatfn="true" ;;
        PHASE.START:__jat__pstart)          meatfn="__jat__log_evt_pstart" ;;
        SESSION.END:jat__sfinish)           meatfn="true" ;;
        SESSION.RELOAD:jat__sinit)          meatfn="true" ;;
        SESSION.START:jat__sinit)           meatfn="true" ;;
        ASSERT.FAIL:__jat__assert)          meatfn="__jat__log_evt_assert" ;;
        ASSERT.PASS:__jat__assert)          meatfn="__jat__log_evt_assert" ;;
        MESSAGE.ERROR:__jat__usage)         meatfn="__jat__log_evt_message" ;;
        MESSAGE.ERROR:jat__log_error)       meatfn="__jat__log_evt_message" ;;
        MESSAGE.INFO:jat__log_info)         meatfn="__jat__log_evt_message" ;;
        MESSAGE.WARNING:jat__log_warning)   meatfn="__jat__log_evt_message" ;;
        *)  __jat__show_error "illegal call of __jat__log_event: $EType from $origin"
            EType=MESSAGE.ERROR ;;
    esac
    echo "$EType" >> "$(__jat__sd_path "vlog")"
    echo "$EType" >> "$(__jat__sd_path "P.vlog")"
    {
        echo "    -"
        echo "        etype: $EType"
        echo "        stamp: $(__jat__newstamp)"
        $meatfn "$@"
    } | __jat__writelog
}

__jat__log_evt_pstart() {
    #
    #     __jat__log_event PHASE.START ID NAME TYPE [pcaseid=CASEID] [pdir=PDIR]
    #
    local pid=$1; shift
    local pname=$1; shift
    local ptype=$1; shift
    local data=("$@")
    echo "        phase:"
    echo "            id: $pid"
    echo "            type: $ptype"
    echo "            name: |-4"
    echo "                $pname"
    __jat__yamld 2 data "${data[@]}"
}

__jat__log_evt_message() {
    #     __jat__log_event MESSAGE.INFO|MESSAGE.WARNING|MESSAGE.ERROR MSG
    local msg=$1; shift
    local data=("$@")
    __jat__yamls 2 message "$msg"
    __jat__yamld 2 data "${data[@]}"
}

__jat__log_evt_assert() {
    #     __jat__log_event ASSERT.PASS|ASSERT.FAIL HINT CASEID [K=V..]
    local hint=$1; shift
    local caseid=$1; shift
    local data=("$@")
    case $caseid in
        "") caseid=$CaseIdBase ;;
        *)  caseid=$CaseIdBase:$caseid ;;
    esac
    __jat__yamls 2 hint "$hint"
    __jat__yamls 2 caseid "$caseid"
    __jat__yamld 2 data "${data[@]}"
}

__jat__newstamp() {
    #
    # Create new timestamp
    #
    case $__JAT__DETERMINISTIC in
        true)   __jat__bumpid time ;;
        false)  date +%s ;;
        *) die "bad value of __JAT__DETERMINISTIC: $__JAT__DETERMINISTIC" ;;
    esac
}

__jat__newsid() {
    #
    # Create new timestamp
    #
    case $__JAT__DETERMINISTIC in
        true)   echo noid ;;
        false)  date +%s-%N ;;
        *) die "bad value of __JAT__DETERMINISTIC: $__JAT__DETERMINISTIC" ;;
    esac
}

__jat__pdummy() {
    #
    # Create dummy phase
    #
    __jat__sd_keyw phase "dummy"
    __jat__sd_keyw P.name "_jat_dummy_phase_"
    __jat__sd_keyw P.type "none"
}

__jat__pstart() {
    #
    # Start phase of type $1 and name $2
    #
    local type      # phase name
    local name      # ^^ name
    local pdir      # ^^ directory
    local pcaseid   # ^^ case id, if assigned
    local oldphase  # current phase id
    local newphase  # new phase id
    while true; do case $1 in
        -t) type="$2"; shift 2 || return 2 ;;
        -c) pcaseid="$2"; shift 2 || return 2 ;;
        -C) pdir="$2"; shift 2 || return 2 ;;
        *)  break ;;
    esac done
    name="${1:-_jat_anon_phase_}"
    oldphase=$(__jat__sd_keyr phase)
    test "$oldphase" == dummy || {
        jat__log_error "old phase not ended; ending automatically: $oldphase"
        jat__pend
    }
    debug -v type name pdir
    newphase=$(__jat__bumpid phasid)
    __jat__sd_keyw phase "$newphase"
    __jat__sd_keyw P.type "$type"
    __jat__sd_keyw P.name "$name"
    __jat__sd_keyw P.pcaseid "$pcaseid"
    __jat__show_pstart "$name"
    __jat__log_event PHASE.START "$newphase" "$name" "$type" "pcaseid=$pcaseid" "pdir=$pdir"
    test -n "$pdir" && {
        __jat__sd_keyw P.pdir "$pdir"
        __jat__sd_keyw P.PWD "$PWD"
        jat__log_info "changing directory for phase: $pdir"
        pushd "$pdir" >/dev/null || {
            jat__log_error "failed to change to phase directory: $pdir"
            return 3
        }
    }
}

__jat__sd_keya() {
    #
    # Append line $2 to session key $1
    #
    local key=$1
    local value=$2
    local path
    path=$(__jat__sd_path "$key")
    echo "$value" >> "$path" || {
        __jat__show_error "error appending session data: key '$key' to '$path'"
        return 3
    }
}

__jat__sd_keyR() {
    #
    # Read session key $1 if it exists, return 1 otherwise
    #
    local key=$1
    local path
    path=$(__jat__sd_path "$key") || return 1
    cat "$path" || {
        __jat__show_error "error reading session data: key '$key' from '$path'"
        return 3
    }
}

__jat__sd_keyr() {
    #
    # Read session key $1
    #
    local key=$1
    local path
    path=$(__jat__sd_path "$key")
    cat "$path" || {
        __jat__show_error "error reading session data: key '$key' from '$path'"
        return 3
    }
}

__jat__sd_keyw() {
    #
    # Write $2 to session key $1
    #
    local key=$1
    local value=$2
    local path
    path=$(__jat__sd_path "$key")
    echo "$value" > "$path" || {
        __jat__show_error "error writing session data: key '$key' to '$path'"
        return 3
    }
}

__jat__sd_path() {
    #
    # Dereference path to session key $1; true if exists
    #
    # Key starting with 'P.' will be phase-specific.
    #
    local key=$1
    local path="$__JAT__SDIR/internal/"
    case $key in
        "")     __jat__show_error "no KEY?"; return 2 ;;
        P.*)    path+="phase-$(__jat__sd_keyr phase)/$key" ;;
        *)      path+="$key" ;;
    esac
    mkdir -p "${path%/*}" 2>/dev/null || {
        __jat__show_error "could not create key: $path"
        return 2
    }
    echo "$path"
    test -e "$path"
}

__jat__show() {
    #
    # Show to user and also keep in ansi log
    #
    local msg
    for msg in "$@"; do
        echo -e "$msg" >> "$__JAT__SDIR/log.ansi"
        echo -e "$msg" >&2
    done
}

__jat__show_fail() {
    #
    # Show assert fail message $1 to stderr
    #
    __jat__show \
        "  $__JAT__SWORD_ASSERT.$__JAT__SWORD_FAIL: $1"
}

__jat__show_pass() {
    #
    # Show assert fail message $1 to stderr
    #
    __jat__show \
        "  $__JAT__SWORD_ASSERT.$__JAT__SWORD_PASS: $1"
}

__jat__show_pend() {
    #
    # Show phase end
    #
    local pverd     # phase verdict text
    local pname     # ^^ name
    local pnhint    # ^^ ^^ display
    local errors    # count of errors
    local warnings  # ^^ warnings
    local asserts   # ^^ asserts
    local fails     # ^^ fails
    pname=$(__jat__sd_keyr P.name)
    errors=$(jat__stat perrc)
    warnings=$(jat__stat pwarc)
    asserts=$(jat__stat pasrtc)
    fails=$(jat__stat pfailc)
    test "$pname" == "_jat_anon_phase_" || pnhint=" '$pname'"
    case $errors:$warnings:$asserts:$fails in
        0:0:0:*) pverd=""                        ;;
        0:0:*:0) pverd=".$__JAT__SWORD_PASS"     ;;
        0:0:*:*) pverd=".$__JAT__SWORD_FAIL"     ;;
        0:*:*:*) pverd=".$__JAT__SWORD_TWARNING" ;;
        *:*:*:*) pverd=".$__JAT__SWORD_TERROR  " ;;
    esac
    __jat__show \
        "$__JAT__SWORD_PHASE.$__JAT__SWORD_END$pverd$pnhint" \
        ""
}

__jat__show_pstart() {
    #
    # Show phase start
    #
    local pname=$1  # phase name
    local pnhint    # ^^ ^^ display
    test "$pname" == "_jat_anon_phase_" || pnhint=" '$pname'"
    __jat__show \
        "$__JAT__SWORD_PHASE.$__JAT__SWORD_START$pnhint"
}

__jat__show_sfinish() {
    #
    # Show message about session $1 finalization to stderr
    #
    local sverd     # session verdict text
    local errors    # count of errors
    local warnings  # ^^ warnings
    local asserts   # ^^ asserts
    local fails     # ^^ fails
    errors=$(jat__stat serrc)
    warnings=$(jat__stat swarc)
    asserts=$(jat__stat sasrtc)
    fails=$(jat__stat sfailc)
    case $errors:$warnings:$asserts:$fails in
        0:0:0:*) sverd=""                        ;;
        0:0:*:0) sverd=".$__JAT__SWORD_PASS"     ;;
        0:0:*:*) sverd=".$__JAT__SWORD_FAIL"     ;;
        0:*:*:*) sverd=".$__JAT__SWORD_TWARNING" ;;
        *:*:*:*) sverd=".$__JAT__SWORD_TERROR"   ;;
    esac
    __jat__show \
        "$__JAT__SWORD_SESSION.$__JAT__SWORD_FINALIZE$sverd"
}

__jat__show_sinitn() {
    #
    # Show message about session initialization to stderr
    #
    __jat__show \
        "$__JAT__SWORD_TEST.$__JAT__SWORD_TINFO: id: $JAT__TEST_ID" \
        "$__JAT__SWORD_TEST.$__JAT__SWORD_TINFO: version: $JAT__TEST_VERSION" \
        "" \
        "$__JAT__SWORD_SESSION.$__JAT__SWORD_START" \
        ""
}

__jat__show_sinitr() {
    #
    # Show message about session reload to stderr
    #
    __jat__show \
        "$__JAT__SWORD_TEST.$__JAT__SWORD_TINFO: id: $JAT__TEST_ID" \
        "$__JAT__SWORD_TEST.$__JAT__SWORD_TINFO: version: $JAT__TEST_VERSION" \
        "" \
        "$__JAT__SWORD_SESSION.$__JAT__SWORD_RELOAD" \
        ""
}

__jat__show_tinfo() {
    #
    # Show test info
    #
    local sp=""
    test "$(__jat__sd_keyr phase)" == dummy || sp="  "
    __jat__show \
        "$sp$__JAT__SWORD_TEST.$__JAT__SWORD_TINFO: $1"
}

__jat__show_terror() {
    #
    # Show test error
    #
    local sp=""
    test "$(__jat__sd_keyr phase)" == dummy || sp="  "
    __jat__show \
        "$sp$__JAT__SWORD_TEST.$__JAT__SWORD_TERROR: $1"
}

__jat__show_twarning() {
    #
    # Show test warning
    #
    local sp=""
    test "$(__jat__sd_keyr phase)" == dummy || sp="  "
    __jat__show \
        "$sp$__JAT__SWORD_TEST.$__JAT__SWORD_TWARNING: $1"
}

__jat__show_error() {
    #
    # Emit general jat warning (not related to SUT)
    #
    warn "jat.ERROR" "$1"
}

__jat__usage() {
    #
    # Print usage error $1 and hint according to FUNCNAME
    #
    local msg=$1
    local parent=${FUNCNAME[1]}
    local patt
    local patts=()
    __jat__show_error "bad usage: $msg"
    case $parent in
        jat__cmd)      patts=("[assert-options] [-o R_OUT] [-e R_ERR] [-s R_ESF] [-S ES_EXPR] [--] CMD [ARG]..") ;;
        jat__eval)     patts=("[assert-options] [-s R_ESF] [-S ES_EXPR] [--] CODE") ;;
        jat__cmp)      patts=("[assert-options] RVAL OP OVAL") ;;
        jat__fail)     patts=("[assert-options]") ;;
        jat__pass)     patts=("[assert-options]") ;;
        jat__submit)   patts=("SRC [ALTNAME]") ;;
        jat__stat)     patts=(spassc sfailc ppassc pfailc) ;;
    esac
    for patt in "${patts[@]}"; do
        __jat__show_error "usage: $parent $patt"
    done
    __jat__log_event MESSAGE.ERROR "bad usage: $parent()" "" \
        "PATTERNS=${patts[*]}"
}

__jat__writelog() {
    #
    # Write logged output (copy if needed)
    #
    case $JAT__YLOG in
        "") cat >> "$__JAT__SDIR/log.yaml" ;;
        -)  tee -a "$__JAT__SDIR/log.yaml" ;;
        *)  tee -a "$__JAT__SDIR/log.yaml" >> "$JAT__YLOG" ;;
    esac
}

__jat__valid_beid() {
    #
    # True if $1 is a valid BEID
    #
    local tainted=$1
    grep -qx '[[:alpha:]_][[:alnum:]_.]*' <<<"$tainted"
}

__jat__valid_pair() {
    #
    # True if $1 is a valid BEID
    #
    local tainted=$1
    grep -qx '\([tor][.]\)\?[[:alpha:]_][[:alnum:]_]*=.*' <<<"$tainted"
}

__jat__yamls() {
    #
    # Print a scalar field named $1 with value $2
    #
    local nest=$1; shift
    local name=$1
    local value=$2
    local sp
    sp=$(__jat__yamlnest "$nest")
    case $value in
        "") echo "$sp$name: ~" ;;
        *)  echo "$sp$name: |-4"
            sed "s/^/$sp    /" <<<"$value" ;;
    esac
}

__jat__yamla() {
    #
    # Print an array field named $1 with array of values $2..
    #
    local nest=$1; shift
    local name=$1; shift
    local value
    local sp
    sp=$(__jat__yamlnest "$nest")
    test $# -eq 0 && echo "    $name: []" && return 0
    echo "$sp$name:"
    for value in "$@"; do
        case $value in
            "") echo "$sp    - ~" ;;
            *)  echo "$sp    - |-4"
                echo "$sp        $value" ;;
        esac
    done
}

__jat__yamlnest() {
    #
    # Print $1 x 4 of spaces
    #
    local n=$1
    while test "$n" -gt 0; do
        echo -n '    '
        (( n-- ))
    done
}

__jat__yamld() {
    #
    # Print a dict field named $1 and composed of KEY=VALUE pairs $2..
    #
    local nest=$1; shift
    local name=$1; shift
    local pair
    local key
    local value
    local sp
    sp=$(__jat__yamlnest "$nest")
    test $# -eq 0 && echo "$sp$name: {}" && return 0
    echo "$sp$name:"
    for pair in "$@"; do
        key=${pair%%=*}; value=${pair#$key=}
        case $value in
            "") echo "$sp    $key: ~" ;;
            *)  echo "$sp    $key: |-4"
                echo "$sp        $value" ;;
        esac
    done
}

#shellfu module-version=__MKIT_PROJ_VERSION__