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.
#
#  *  `-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.
#
#
# 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 name* - 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__TESTID=${JAT__TESTID:-_jat_anon_test_}

#
# Path to main logfile
#
__JAT__SDIR=

#
# 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=true

#
# 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 $@ returns zero (or other)
    #
    # Usage:
    #
    #     jat__cmd [-o R_OUT] [-e R_ERR] [-S ES_EXPR] [--] CMD [ARG]..
    #
    # Run CMD with all ARGs and if exit status is zero, announce assertion
    # success (PASS), otherwise announce assertion failure (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 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.
    #
    local __jat__cmd=()
    local __jat__r_es
    local __jat__o_es=0
    local __jat__hint
    local __jat__beids=()
    local __jat__etype=TEST_ERROR
    local __jat__r_out
    local __jat__r_err
    #
    # 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; } ;;
        -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__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
    if __jat__es_match "$__jat__o_es" "$__jat__r_es"; then
        __jat__etype=PASS
    else
        __jat__etype=FAIL
    fi
    __jat__assert $__jat__etype "$__jat__hint" "${__jat__beids[@]}" \
        -- "CMDLINE=${__jat__cmd[*]}" "ES_EXPR=$__jat__o_es" "ES=$__jat__r_es"
    return "$__jat__r_es"
}

jat__cmp() {
    #
    # Assert that value $@ returns zero (or other)
    #
    # Usage:
    #
    #     jat__cmp [assert-options] RVAL OP OVAL
    #
    # Compare RVAL (result value) to OVAL (oracle value) and announce
    # assertion success (PASS) or assertion failure (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 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; } ;;
        -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 PASS "$hint" "${beids[@]}" \
                -- "RVAL=$RVal" "OP=$Op" "OVAL=$OVal"
            ;;
        1)
            __jat__assert FAIL "$hint" "${beids[@]}" \
                -- "RVAL=$RVal" "OP=$Op" "OVAL=$OVal"
            ;;
        *)
            __jat__usage "bad syntax: $RVal $Op $OVal"
            return 2
            ;;
    esac
}

jat__eval() {
    #
    # Assert that command in code $1 returns zero (or other)
    #
    # Usage:
    #
    #     jat__eval [-S ES_EXPR] [--] CODE
    #
    # Run CODE using eval builtin and if exit status is zero, announce assertion
    # success (PASS), otherwise announce assertion failure (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.
    #
    # This is similar to jat__cmd(), except that code is checked agains syntax
    # errors and user is given slightly full control over redirections.
    #
    # See COMMON ARGUMENTS section for common assert options.
    #
    local __jat__code=""
    local __jat__r_es
    local __jat__o_es=0
    local __jat__hint
    local __jat__beids=()
    local __jat__etype=TEST_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; } ;;
        -h) __jat__hint=$2; shift 2 || { __jat__usage "missing HINT"; 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=$?
    debug -v __jat__r_es
    if __jat__es_match "$__jat__o_es" "$__jat__r_es"; then
        __jat__etype=PASS
    else
        __jat__etype=FAIL
    fi
    __jat__assert $__jat__etype "$__jat__hint" "${__jat__beids[@]}" \
        -- "CODE=$__jat__code" "ES_EXPR=$__jat__o_es" "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 beids=()  # Behavior Evidence IDs
    while true; do case $1 in
        -b) beids+=("$2"); shift 2 || { __jat__usage "missing BEID"; 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 FAIL "$hint" "${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
    test -d "$JAT__DIR/session" || {
        __jat__show_error "no active session: no $JAT__DIR/session"
        return 2
    }
    __jat__show_sfinish
    __jat__log_event SINFO "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"
}

jat__log_error() {
    #
    # Log internal error unrelated to SUT
    #
    local msg=$1
    echo "error" >> "$(__jat__sd_path "llog")"
    echo "error" >> "$(__jat__sd_path "P.llog")"
    __jat__log_event TEST_ERROR "$msg"
    __jat__show_terror "$msg"
}

jat__log_info() {
    #
    # Log internal info unrelated to SUT
    #
    local msg=$1
    echo "info" >> "$(__jat__sd_path "llog")"
    echo "info" >> "$(__jat__sd_path "P.llog")"
    __jat__log_event SINFO "$msg"
    __jat__show_tinfo "$msg"
}

jat__log_warning() {
    #
    # Log internal error unrelated to SUT
    #
    local msg=$1
    echo "warning" >> "$(__jat__sd_path "llog")"
    echo "warning" >> "$(__jat__sd_path "P.llog")"
    __jat__log_event TEST_WARNING "$msg"
    __jat__show_twarning "$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
    while true; do case $1 in
        -b) beids+=("$2"); shift 2 || { __jat__usage "missing BEID"; 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 PASS "$hint" "${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 PROMISE "assert number: $num" \
        -- "num=$num"
}

jat__sinit() {
    #
    # Initialize session
    #
    # Load active session if found; otherwise initialize new one.
    #
    local reload=false
    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
        __jat__log_event SINFO "reloaded session" \
            -- \
            "JAT__LOG_FMT=$__JAT__LOG_FMT" \
            "JAT__VERSION=$__JAT__SELF_VERSION"
        __jat__show_sinitr
    else
        debug -v __JAT__SDIR JAT__YLOG
        {
            echo "---"
            echo "format: $__JAT__LOG_FMT"
            echo "jat_version: $__JAT__SELF_VERSION"
            echo "test:"
            echo "    id: $JAT__TESTID"
            echo "start: $(__jat__newstamp)"
            echo "events:"
        } | __jat__writelog
        __jat__pdummy
        __jat__log_event SINFO "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 warning "$(__jat__sd_path "llog")" ;;
        pwarc)  grep -cxF warning "$(__jat__sd_path "P.llog")" ;;
        serrc)  grep -cxF error "$(__jat__sd_path "llog")" ;;
        perrc)  grep -cxF error "$(__jat__sd_path "P.llog")" ;;
        sfailc) grep -cxF FAIL "$(__jat__sd_path "vlog")" ;;
        pfailc) grep -cxF FAIL "$(__jat__sd_path "P.vlog")" ;;
        ppassc) grep -cxF PASS "$(__jat__sd_path "P.vlog")" ;;
        spassc) grep -cxF PASS "$(__jat__sd_path "vlog")" ;;
        pasrtc) grep -cx 'PASS\|FAIL' "$(__jat__sd_path "P.vlog")" ;;
        sasrtc) grep -cx 'PASS\|FAIL' "$(__jat__sd_path "vlog")" ;;
        *) __jat__usage "invalid statistic field: $which"
           return 2 ;;
    esac
}

jat__pend() {
    #
    # End active phase
    #
    local oldpdir
    oldpdir=$(__jat__sd_keyR P.pdir)
    test -n "$oldpdir" && {
        jat__log_info "changing back from phase dir: $oldpdir"
        popd >/dev/null
    }
    __jat__show_pend
    __jat__pdummy
    __jat__log_event SINFO
}

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
    }
    test -n "$altname" && {
        dest="$dest/$altname"
        nhint=" as $altname"
    }
    mkdir -p "$(dirname "$dest")" || {
        jat__log_error "cannot write to result storage: $dest"
        return 3
    }
    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
        PASS)   __jat__show_pass "$2" ;;
        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__log_event() {
    #
    # Pass YAML log event to __jat__writelog()
    #
    # Usage:
    #
    #     __jat__log_event ETYPE HINT [BEID].. -- [KEY=VALUE]..
    #
    # ETYPE can be FAIL, PASS, TEST_ERROR or SINFO (the latter two
    # are for events unrelated to SUT, like internal errors or
    # phase start/end events).
    #
    # HINT and BEIDs are explained in COMMON ARGUMENTS section of this
    # manual.
    #
    # You can provide any amount of KEY=VALUE pairs, meaning of which
    # is specific to every assert function.  (The assert function name
    # is auto-detected and logged so that you can infer KEY meanings
    # later.)
    #
    local etype=$1; shift
    local hint=$1;    shift
    local arg
    local beids=()
    local pairs=()
    local real_beids=()
    local reading=beids
    local pair
    local origin=${FUNCNAME[1]}
    case $etype in
        PASS|FAIL|SINFO|TEST_ERROR|TEST_WARNING|PROMISE) : ;;
        *)  __jat__show_error "bad ETYPE, changing to TEST_ERROR: $etype"
            etype=TEST_ERROR ;;
    esac
    case $etype:$origin in
        PASS:__jat__assert)        : ;;
        FAIL:__jat__assert)        : ;;
        TEST_ERROR:__jat__usage)   : ;;
        SINFO:jat__sinit)          : ;;
        SINFO:jat__sfinish)        : ;;
        SINFO:__jat__pstart)       : ;;
        SINFO:jat__pend)           : ;;
        SINFO:jat__log_info)       : ;;
        TEST_ERROR:jat__log_error) : ;;
        TEST_WARNING:jat__log_warning) : ;;
        *)  __jat__show_error "illegal call of __jat__log_event: $etype from $origin"
            etype=TEST_ERROR ;;
    esac
    for arg in "$@"; do
        case $reading:$arg in
            *:)
                shift
                ;;
            beids:--)
                shift
                reading=pairs
                ;;
            beids:*)
                __jat__valid_beid "$arg" || {
                    beids=(); pairs=(); etype=API_BUG
                    hint="bad BEID syntax (must be simple id): '$arg'"
                    __jat__show_error "$hint"
                    break
                }
                beids+=("$arg")
                shift
                ;;
            pairs:*)
                __jat__valid_pair "$arg" || {
                    beids=(); pairs=(); etype=API_BUG
                    hint="bad K=V syntax: '$arg'"
                    __jat__show_error "$hint"
                    break
                }
                pairs+=("$arg")
                shift
                ;;
        esac
    done
    for beid in "${beids[@]}"; do
        case $beid in
            "")     : ;;
            *.*)    real_beids+=("$beid") ;;
            *)      real_beids+=("$JAT__BEID_NS.$beid") ;;
        esac
    done
    echo "$etype" >> "$(__jat__sd_path "vlog")"
    echo "$etype" >> "$(__jat__sd_path "P.vlog")"
    {
        # NOTE: some scalars are printed directly for performance
        #       reasons (these will never be null nor will they
        #       contain YAML special chars)
        #
        echo "-"
        echo "    origin: $origin"
        echo "    etype: $etype"
        echo "    stamp: $(__jat__newstamp)"
        __jat__yamls hint "$hint"
        __jat__yamla beids "${real_beids[@]}"
        __jat__yamld data "${pairs[@]}"
        echo "    phase:"
        echo "        id: $(__jat__sd_keyr phase)"
        echo "        name: $(__jat__sd_keyr P.name)"
        echo "        type: $(__jat__sd_keyr P.type)"
    } | sed 's/^/    /' | __jat__writelog
}

__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__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 oldphase  # current phase id
    while true; do case $1 in
        -t) type="$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
    __jat__sd_keyw phase "$(__jat__bumpid phasid)"
    __jat__sd_keyw P.type "$type"
    __jat__sd_keyw P.name "$name"
    __jat__show_pstart "$name"
    __jat__log_event SINFO
    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 \
        "  ${TERMCOLORS_YELLOW}sut${TERMCOLORS_NONE}.${TERMCOLORS_RED}FAIL${TERMCOLORS_NONE}: $1"
}

__jat__show_pass() {
    #
    # Show assert fail message $1 to stderr
    #
    __jat__show \
        "  ${TERMCOLORS_YELLOW}sut${TERMCOLORS_NONE}.${TERMCOLORS_GREEN}PASS${TERMCOLORS_NONE}: $1"
}

__jat__show_pend() {
    #
    # Show phase end
    #
    local pverd     # phase verdict text
    local pname     # ^^ name
    local pnhint    # ^^ ^^ display
    pname=$(__jat__sd_keyr P.name)
    test "$pname" == "_jat_anon_phase_" || pnhint=" '$pname'"
    case "$(jat__stat pfailc)" in
        0)  pverd="${TERMCOLORS_GREEN}PASS${TERMCOLORS_NONE}" ;; 
        *)  pverd="${TERMCOLORS_RED}FAIL${TERMCOLORS_NONE}" ;;
    esac
    __jat__show \
        "${TERMCOLORS_YELLOW}phase${TERMCOLORS_NONE}.${TERMCOLORS_LBLACK}END${TERMCOLORS_NONE}.$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 \
        "${TERMCOLORS_YELLOW}phase${TERMCOLORS_NONE}.${TERMCOLORS_LBLACK}START${TERMCOLORS_NONE}$pnhint"
}

__jat__show_sfinish() {
    #
    # Show message about session $1 finalization to stderr
    #
    local sverd         # session verdict text
    case "$(jat__stat sfailc)" in
        0)  sverd="${TERMCOLORS_GREEN}PASS${TERMCOLORS_NONE}" ;; 
        *)  sverd="${TERMCOLORS_RED}FAIL${TERMCOLORS_NONE}" ;;
    esac
    __jat__show \
        "${TERMCOLORS_YELLOW}session${TERMCOLORS_NONE}.${TERMCOLORS_LBLACK}FINALIZE${TERMCOLORS_NONE}.$sverd"
}

__jat__show_sinitn() {
    #
    # Show message about session initialization to stderr
    #
    __jat__show \
        "${TERMCOLORS_YELLOW}session${TERMCOLORS_NONE}.${TERMCOLORS_LBLACK}START${TERMCOLORS_NONE}" \
        ""
}

__jat__show_sinitr() {
    #
    # Show message about session reload to stderr
    #
    __jat__show \
        "${TERMCOLORS_YELLOW}session${TERMCOLORS_NONE}.${TERMCOLORS_LBLUE}RELOAD${TERMCOLORS_NONE}" \
        ""
}

__jat__show_tinfo() {
    #
    # Show test info
    #
    local sp=""
    test "$(__jat__sd_keyr phase)" == dummy || sp="  "
    __jat__show \
        "$sp${TERMCOLORS_YELLOW}test${TERMCOLORS_NONE}.${TERMCOLORS_LBLACK}INFO${TERMCOLORS_NONE}: $1"
}

__jat__show_terror() {
    #
    # Show test error
    #
    local sp=""
    test "$(__jat__sd_keyr phase)" == dummy || sp="  "
    __jat__show \
        "$sp${TERMCOLORS_YELLOW}test${TERMCOLORS_NONE}.${TERMCOLORS_RED}ERROR${TERMCOLORS_NONE}: $1"
}

__jat__show_twarning() {
    #
    # Show test warning
    #
    local sp=""
    test "$(__jat__sd_keyr phase)" == dummy || sp="  "
    __jat__show \
        "$sp${TERMCOLORS_YELLOW}test${TERMCOLORS_NONE}.${TERMCOLORS_RED}WARNING${TERMCOLORS_NONE}: $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] [-e ES_EXPR] [--] CMD [ARG]..") ;;
        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 TEST_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 '[[:alpha:]_][[:alnum:]_]*=.*' <<<"$tainted"
}

__jat__yamls() {
    #
    # Print a scalar field named $1 with value $2
    #
    local name=$1
    local value=$2
    case $value in
        "") echo "    $name: ~" ;;
        *)  echo "    $name: |-"
            echo "        $value" ;;
    esac
}

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

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

#shellfu module-version=__MKIT_PROJ_VERSION__