Create a global debug/trace log viewer

Using fzf in zlogtail allowed for easy searching of debug log lines, but
it discarded the context when searching for a term. `ztrace` has been
created to provide further structure to debug log messages and to
subsequently keep it while viewing / searching the messages.

Debug log messages now take the following form:

ZBM:[pid]|<function,file,line;..>|<log message>

The function stack is automatically calculated and inserted into the
debug message. A fully generated message from inside a second function
would look like this:

ZBM:[556]|main,/bin/zfsbootmenu,124;draw_be,/lib/zfsbootmenu-lib.sh,493|selected:
mod-r,ztest/ROOT/void

The PID of the program that generated the message is 556.

The main function, in /bin/zfsbootmenu at line 124 made the first call
The draw_be function, in /lib/zfsbootmenu-lib.sh at line 493 made the
zdebug call with the text 'selected: mod-r,ztest/ROOT/void' .

This format allows for semi-readable raw messages in `dmesg` with out
any color escape sequences, wrapped lines, etc.

ztrace unpacks the log message and rewrites it to the following form:

[ time stamp ] ZBM[pid]: debug message
[ time stamp ]    trace: first function
[ time stamp ]    trace:  second function
[ time stamp ]    trace:   ...

The output is piped into `less`, which can decode the color escape
sequences inserted by ztrace. It allows for searching and highlighting a
term via `/term`.  Lastly, MOD+T has been globally added to all ZBM
screens to bring up ztrace viewing the up-to-date debug log buffer.

Unlike `zlogtail`, `ztrace` does not follow logs. It shows the current
log buffer and then waits for you to search or quit. Quit ztrace via `q`
and then bring it up again to view new messages.

Closes #198

90zfsbootmenu/module-setup.sh

@@ -154,6 +154,7 @@ install() {
   inst_simple "${moddir}/zfs-chroot.sh" "/bin/zfs-chroot" || _ret=$?
   inst_simple "${moddir}/zfsbootmenu.sh" "/bin/zfsbootmenu" || _ret=$?
   inst_simple "${moddir}/zlogtail.sh" "/bin/zlogtail" || _ret=$?
+  inst_simple "${moddir}/ztrace.sh" "/bin/ztrace" || _ret=$?
   inst_hook cmdline 95 "${moddir}/zfsbootmenu-parse-commandline.sh" || _ret=$?
   inst_hook pre-mount 90 "${moddir}/zfsbootmenu-preinit.sh" || _ret=$?
 
@@ -272,13 +273,6 @@ install() {
     mark_hostonly /etc/hostid
   fi
 
-  # Check if dmesg supports --noescape
-  if dmesg --noescape -V >/dev/null 2>&1 ; then
-    has_escape=1
-  else
-    has_escape=
-  fi
-
   # Check if fuzzy finder supports the refresh-preview flag
   # Added in fzf 0.22.0
   if command -v "${FUZZY_FIND}" >/dev/null 2>&1 && \
@@ -303,7 +297,6 @@ install() {
   # shellcheck disable=SC2154
   cat << EOF > "${initdir}/etc/zfsbootmenu.conf"
 export BYTE_ORDER=${endian:-le}
-export HAS_NOESCAPE=${has_escape}
 export HAS_REFRESH=${has_refresh}
 export HAS_INFO=${has_info}
 EOF

90zfsbootmenu/zfsbootmenu-lib.sh

@@ -9,38 +9,29 @@
 # returns: nothing
 
 zlog() {
-  local _script _func prefix offset join _WIDTH
+  local prefix trace last
   [ -z "${1}" ] && return
   [ -z "${2}" ] && return
 
   # Assume a default log severity of "warning" if not specified
   # shellcheck disable=SC2154
   [ "${1}" -le "${loglevel:=4}" ] || return
 
-  # shellcheck disable=SC2086
-  _script="$( basename -- $0 )"
-  _func="${FUNCNAME[2]}"
-
-  # Only add script/function tracing to debug messages
-  if [ "${1}" -eq 7 ] && [ -n "${HAS_NOESCAPE}" ] ; then
-    prefix="<${1}>ZBM:\033[0;33m${_script}[$$]\033[0;31m:${_func}()\033[0m"
-  elif [ "${1}" -eq 7 ]; then
-    prefix="<${1}>ZBM:${_script}[$$]:${_func}()"
-  else
-    prefix="<${1}>ZFSBootMenu"
-  fi
-
-  offset="${#prefix}"
-
-  # account for the fzf gutter and kernel timestamp
-  [ -z "${COLUMNS}" ] && COLUMNS="$( tput cols )"
-  _WIDTH=$(( COLUMNS - ( offset - 15 ) ))
+  while IFS=$'\n' read -r line ; do
+    # Only add script/function tracing to debug messages
+    if [ "${1}" -eq 7 ] ; then
+      trace=
+      last=${#BASH_SOURCE[@]}
+      for (( i=2 ; i<last ; i++ )); do
+        trace="${FUNCNAME[$i]},${BASH_SOURCE[$i]},${BASH_LINENO[$i-1]}${trace:+;}${trace}"
+      done
+      prefix="<${1}>ZBM:[$$]|${trace}|"
+    else
+      prefix="<${1}>ZFSBootMenu: "
+    fi
 
-  join=': '
-  while read -r line; do
-    echo -e "${prefix}${join}${line}" > /dev/kmsg
-    join='+   '
-  done <<<"$( echo "${2}" | fold -s -w "${_WIDTH}" )"
+    echo -e "${prefix}${line}" > /dev/kmsg
+  done <<<"${2}"
 }
 
 # arg1: log line

90zfsbootmenu/zfsbootmenu-preinit.sh

@@ -36,6 +36,7 @@ export default_hostid=00bab10c
 export zbm_sort="${zbm_sort}"
 export zbm_set_hostid="${zbm_set_hostid}"
 export zbm_import_delay="${zbm_import_delay}"
+export control_term="${control_term}"
 EOF
 
 getcmdline > "${BASE}/zbm.cmdline"

90zfsbootmenu/zfsbootmenu.sh

@@ -72,7 +72,10 @@ fuzzy_default_options=( "--ansi" "--no-clear"
   "--layout=reverse-list" "--inline-info" "--tac" "--color=16"
   "--bind" '"alt-h:execute[ /libexec/zfsbootmenu-help -L ${HELP_SECTION:-main-screen} ]"'
   "--bind" '"ctrl-h:execute[ /libexec/zfsbootmenu-help -L ${HELP_SECTION:-main-screen} ]"'
-  "--bind" '"ctrl-alt-h:execute[ /libexec/zfsbootmenu-help -L ${HELP_SECTION:-main-screen} ]"' )
+  "--bind" '"ctrl-alt-h:execute[ /libexec/zfsbootmenu-help -L ${HELP_SECTION:-main-screen} ]"'
+  "--bind" '"alt-t:execute[ /sbin/ztrace > ${control_term} ]"'
+  "--bind" '"ctrl-t:execute[ /sbin/ztrace > ${control_term} ]"'
+  "--bind" '"ctrl-alt-t:execute[ /sbin/ztrace > ${control_term} ]"' )
 
 if [ -n "${HAS_REFRESH}" ] ; then
   fuzzy_default_options+=(

90zfsbootmenu/zlogtail.sh

@@ -31,8 +31,6 @@ while getopts "cfnl:F:" opt; do
   esac
 done
 
-[ -n "${HAS_NOESCAPE}" ] && NOESCAPE="--noescape"
-
 fuzzy_default_options+=(
  "--no-sort"
  "--ansi"
@@ -63,6 +61,6 @@ elif command -v sk >/dev/null 2>&1; then
 fi
 
 # shellcheck disable=SC2086
-( dmesg -T --time-format reltime ${NOESCAPE} -f ${FACILITY} -l ${LOG_LEVEL} ${FOLLOW} & echo $! >&3 ) \
+( dmesg -T --time-format reltime -f ${FACILITY} -l ${LOG_LEVEL} ${FOLLOW} & echo $! >&3 ) \
   3>"${PID_FILE}" \
   | ${FUZZYSEL}

90zfsbootmenu/ztrace.sh

@@ -0,0 +1,34 @@
+#!/bin/bash
+#shellcheck disable=SC2086
+
+r="\033[0;31m"
+g="\033[0;32m"
+o="\033[0;33m"
+n="\033[0m"
+
+while read -r line ; do
+  time="${line:0:13}"
+  suffix="${line:14:${#line}}"
+
+  if [ "${suffix:0:3}" != "ZBM" ]; then
+    continue
+  fi
+
+  IFS='|' read -r prefix trace log <<<"${suffix}"
+  IFS=';' read -ra tokens <<<"${trace}"
+
+  ppref="$( printf "%*s" 11 "${prefix}:" )"
+  tpref="$( printf "%*s" 11 "trace:" )"
+
+  pad=' '
+  c="${g}"
+
+  echo -e "${time} ${ppref} ${log}"
+  for token in "${tokens[@]}" ; do
+    IFS=',' read -r func file line <<<"${token}"
+    echo -e "${time} ${tpref}${pad}${r}${func}@${c}${file}${n}#${line}"
+    pad="${pad} "
+    c="${o}"
+  done
+
+done < <( dmesg -T --time-format reltime -f user -l 7 ) | less -R -S +G