sdp_structured_log.sh #4

#!/bin/bash
# shellcheck shell=bash
#==============================================================================
# Copyright and license info is available in the LICENSE file included with
# the Server Deployment Package (SDP), and also available online:
# https://swarm.workshop.perforce.com/projects/perforce-software-sdp/view/main/LICENSE
#------------------------------------------------------------------------------
#
# sdp_structured_log.sh -- shared structured-logging helper for SDP
# maintenance scripts. Sourced automatically by backup_functions.sh.
#
# One mode at a time, not simultaneous dual-writing: SDP_LOG_FORMAT (set in
# p4_vars) selects jsonl (default), prom, or off.
#   jsonl - one JSON object per run, appended alongside the calling script's
#           own $LOGFILE (same base name, .jsonl extension instead of .log).
#   prom  - Prometheus textfile-collector gauges written to $SDP_METRICS_DIR
#           instead, one file per script, atomically (write-to-tempfile-then-
#           mv), matching the convention perforce-sdp-monitoring's own
#           p4_healthcheck.sh.j2 already uses.
#   off   - no structured output at all.
#
# Usage, from a script that already sources p4_vars + backup_functions.sh:
#   LOGFILE="$LOGS/myscript.log"
#   log_init
#   sdp_log_init                 # after LOGFILE/log_init, before script logic
#   ...
#   sdp_add_field key value      # zero or more, any point before exit
#   ...                          # exit normally, via die(), or via a signal --
#                                 # the terminal record is emitted exactly
#                                 # once regardless, from the EXIT trap.
#
# A script that wants to emit one record itself, without the trap machinery
# (e.g. because it has its own error handling already), can call
# sdp_log_event directly instead of sdp_log_init.
#
# Every write is best-effort and never fatal: a logging failure must not turn
# a successful checkpoint into a failed one, and must never write to stdout
# -- some callers (trigger scripts) cannot have anything on stdout at all,
# since p4d relays a trigger's stdout to the connected client.
#------------------------------------------------------------------------------

[[ -n "${_SDP_STRUCTURED_LOG_LOADED:-}" ]] && return 0
_SDP_STRUCTURED_LOG_LOADED=1

#------------------------------------------------------------------------------
# sdp_log_init [script-name]
#
# Call once, after LOGFILE (if any) is set and after log_init. Initializes
# per-run state and installs the trap that guarantees exactly one terminal
# record gets emitted regardless of how the script exits -- clean exit,
# explicit exit N, die(), an unbound variable under set -u, a set -e command
# failure, or HUP/INT/TERM. (SIGKILL/OOM cannot be trapped by any shell; that
# is a documented limitation, not a gap in this helper.)
#
# Placement matters for wrapper scripts like run_if_master.sh: call this
# AFTER any role-gate check that should exit silently (e.g. "this host is
# not a master, skip"), so a legitimate skip emits nothing.
#------------------------------------------------------------------------------
function sdp_log_init () {
   SDP_SCRIPT_NAME="${1:-${0##*/}}"
   SDP_EVENT_START=$(_sdp_now)
   SDP_EVENT_STATUS=success
   SDP_EVENT_ERROR=
   SDP_EVENT_EXTRA=()
   _SDP_EVENT_EMITTED=0

   trap '_sdp_on_exit $?' EXIT
   trap '_sdp_trap_err $?' ERR
   trap '_sdp_trap_signal HUP'  HUP
   trap '_sdp_trap_signal INT'  INT
   trap '_sdp_trap_signal TERM' TERM
}

#------------------------------------------------------------------------------
# sdp_add_field <key> <value>   (or a single "key=value" argument)
#
# Accumulates script-specific "what happened" data for the terminal record.
# Written flat alongside the fixed fields -- no nested object. Numeric
# values become numeric fields; anything else is quoted (jsonl) or dropped
# (prom -- a gauge value must be a number).
#------------------------------------------------------------------------------
function sdp_add_field () {
   local kv
   if [[ $# -ge 2 ]]; then
      kv="$1=$2"
   else
      kv=$1
   fi
   SDP_EVENT_EXTRA+=("$kv")
}

#------------------------------------------------------------------------------
# sdp_set_status <success|warning|failure>
#
# Monotonic downgrade only (success -> warning -> failure), so a later
# success can never mask an earlier warning or failure from the same run.
#------------------------------------------------------------------------------
function sdp_set_status () {
   local new=${1:-success}
   local cur=${SDP_EVENT_STATUS:-success}
   case "$cur:$new" in
      *:failure)          SDP_EVENT_STATUS=failure ;;
      success:warning)    SDP_EVENT_STATUS=warning ;;
      failure:*|warning:success|warning:warning) : ;; # never upgrade / already there
      *)                  SDP_EVENT_STATUS=$new ;;
   esac
}

#------------------------------------------------------------------------------
# sdp_set_error <message>
#------------------------------------------------------------------------------
function sdp_set_error () {
   SDP_EVENT_ERROR=${1:0:900}
}

#------------------------------------------------------------------------------
# sdp_elapsed
#
# Echoes elapsed seconds (float) since sdp_log_init. Falls back to the
# shell's own $SECONDS (integer) if the platform's date lacks %N (e.g. BSD).
#------------------------------------------------------------------------------
function sdp_elapsed () {
   local start=${SDP_EVENT_START:-}
   [[ -z "$start" ]] && { echo 0; return 0; }
   case "$start" in
      *N) echo "$SECONDS"; return 0 ;;
   esac
   "${AWK:-awk}" -v s="$start" -v n="$(_sdp_now)" 'BEGIN{printf "%.3f", n-s}' 2>/dev/null || echo "$SECONDS"
}

#------------------------------------------------------------------------------
# sdp_log_event <status> <exit_code> <duration_seconds> [error] [key=value ...]
#
# The single writer, dispatching on SDP_LOG_FORMAT. Never fatal.
#------------------------------------------------------------------------------
function sdp_log_event () {
   local status=${1:-success} exit_code=${2:-0} duration=${3:-0} error=${4:-}
   local extra=()
   if [[ $# -gt 4 ]]; then
      extra=("${@:5}")
   fi

   case "${SDP_LOG_FORMAT:-jsonl}" in
      off)  : ;;
      prom) _sdp_write_prom  "$status" "$exit_code" "$duration" "$error" "${extra[@]+"${extra[@]}"}" ;;
      *)    _sdp_write_jsonl "$status" "$exit_code" "$duration" "$error" "${extra[@]+"${extra[@]}"}" ;;
   esac

   # Only mirror into the human-readable log when there IS one. log()'s own
   # fallback for no $LOGFILE is to echo to stdout (correct for log()'s
   # other, general-purpose callers) -- but that is exactly the "never
   # write to stdout" invariant this module documents at the top of this
   # file, and the run_if_{master,edge,replica,broker,proxy}.sh wrapper
   # family deliberately never sets LOGFILE (they share one .jsonl keyed by
   # script name instead of a *.log sibling - see _sdp_structured_file).
   # Confirmed live: every cron run through any of those wrappers was
   # echoing this line to stdout, success or not, and cron mails on any
   # output -- not gated on LOGFILE, this fired on 100% of runs, not just
   # failures.
   if declare -F log >/dev/null 2>&1 && [[ -n "${LOGFILE:-}" ]]; then
      log "sdp_event script=${SDP_SCRIPT_NAME:-${0##*/}} status=$status exit_code=$exit_code duration=${duration}s" 2>/dev/null
   fi
   return 0
}

#==============================================================================
# Private helpers below. Names are prefixed _sdp_ specifically so they can
# never collide with any script's own locals -- e.g. run_if_master.sh and
# friends already define a local check_vars() that shadows
# backup_functions.sh's own, so name collision here is a real, observed risk
# class, not a theoretical one.
#==============================================================================

function _sdp_now () {
   date +%s.%N 2>/dev/null
}

function _sdp_json_escape () {
   local s=$1
   s=${s//\\/\\\\}
   s=${s//\"/\\\"}
   s=${s//$'\t'/\\t}
   s=${s//$'\r'/\\r}
   s=${s//$'\n'/\\n}
   printf '%s' "$s"
}

# The jsonl sibling of the calling script's own log, or a fixed fallback
# under $LOGS when no LOGFILE is set (e.g. the run_if_*.sh wrappers, which
# share one cron_wrapper.jsonl rather than each defining their own LOGFILE).
function _sdp_structured_file () {
   if [[ -n "${LOGFILE:-}" ]]; then
      case "$LOGFILE" in
         *.log) echo "${LOGFILE%.log}.jsonl" ;;
         *)     echo "${LOGFILE}.jsonl" ;;
      esac
   else
      echo "${LOGS:-/tmp}/${SDP_SCRIPT_NAME:-cron_wrapper}.jsonl" | sed 's/\.sh\.jsonl$/.jsonl/'
   fi
}

# PIPE_BUF rule: a single printf of a line <= 4096 bytes to a file opened
# O_APPEND is atomic on Linux, which is what makes concurrent appends to a
# shared .jsonl (e.g. daily_checkpoint.sh + rotate_journal.sh sharing
# checkpoint.jsonl) safe without any locking. Enforced here by truncating
# the error message and every extra value, and capping the total line
# length -- never remove these caps without replacing the append with a
# real lock.
function _sdp_write_jsonl () {
   local status=$1 exit_code=$2 duration=$3 error=$4
   shift 4 || return 0
   local file dir
   file=$(_sdp_structured_file)
   dir=$(dirname "$file")
   [[ -d "$dir" && -w "$dir" ]] || return 1

   local error_json
   if [[ -z "$error" ]]; then
      error_json=null
   else
      error_json="\"$(_sdp_json_escape "${error:0:900}")\""
   fi

   local line
   # %:z (not `date -Iseconds`/%z) to force a colon-separated UTC offset
   # (+00:00, not +0000) - matches sdp_structured_log.py's
   # datetime.isoformat(), which always includes the colon. `-Iseconds`
   # does NOT reliably match: on GNU coreutils 8.22 (RHEL7-family, still
   # in the field) it emits +0000, no colon - confirmed live
   # (5332stage.p4one.ea.com) - while telegraf's json_time_format for
   # *.jsonl (perforceone.j2) is the single Go layout "2006-01-02T15:04:05Z07:00",
   # which requires the colon and rejects +0000 as unparseable, silently
   # dropping every line this script emits. %:z is unambiguous regardless
   # of coreutils version.
   line=$(printf '{"timestamp":"%s","script":"%s","instance":"%s","status":"%s","exit_code":%s,"duration_seconds":%s,"error":%s' \
      "$(date '+%Y-%m-%dT%H:%M:%S%:z')" \
      "$(_sdp_json_escape "${SDP_SCRIPT_NAME:-${0##*/}}")" \
      "$(_sdp_json_escape "${SDP_INSTANCE:-}")" \
      "$(_sdp_json_escape "$status")" \
      "${exit_code:-0}" \
      "${duration:-0}" \
      "$error_json")

   local kv k v total=${#line}
   for kv in "$@"; do
      [[ "$kv" == *=* ]] || continue
      k=${kv%%=*}
      v=${kv#*=}
      v=${v:0:256}
      if [[ "$v" =~ ^-?[0-9]+(\.[0-9]+)?$ ]]; then
         kv=",\"$(_sdp_json_escape "$k")\":$v"
      else
         kv=",\"$(_sdp_json_escape "$k")\":\"$(_sdp_json_escape "$v")\""
      fi
      if (( total + ${#kv} > 3900 )); then
         line+=',"truncated":true'
         break
      fi
      line+="$kv"
      total=$(( total + ${#kv} ))
   done
   line+='}'

   printf '%s\n' "$line" >> "$file" 2>/dev/null
}

function _sdp_metric_base () {
   local name="p4_sdp_${SDP_SCRIPT_NAME%.*}"
   name=${name//[^a-zA-Z0-9_]/_}
   printf '%s' "$name"
}

function _sdp_prom_label_escape () {
   local s=${1:0:128}
   s=${s//\\/\\\\}
   s=${s//\"/\\\"}
   s=${s//$'\n'/\\n}
   printf '%s' "$s"
}

function _sdp_write_prom () {
   local status=$1 exit_code=$2 duration=$3 error=$4
   shift 4 || return 0
   local dir="${SDP_METRICS_DIR:-/p4/metrics}"
   [[ -d "$dir" && -w "$dir" ]] || return 1

   local base instance file tmp success
   base=$(_sdp_metric_base)
   instance=$(_sdp_prom_label_escape "${SDP_INSTANCE:-}")
   file="${dir}/${base}.prom"
   tmp="${file}.$$"
   success=1
   [[ "$status" == success ]] || success=0

   {
      echo "# HELP ${base}_success Whether the last run of this script succeeded (1) or not (0)."
      echo "# TYPE ${base}_success gauge"
      echo "${base}_success{instance=\"$instance\"} $success"

      echo "# HELP ${base}_exit_code Exit code of the last run."
      echo "# TYPE ${base}_exit_code gauge"
      echo "${base}_exit_code{instance=\"$instance\"} ${exit_code:-0}"

      echo "# HELP ${base}_duration_seconds Duration of the last run, in seconds."
      echo "# TYPE ${base}_duration_seconds gauge"
      echo "${base}_duration_seconds{instance=\"$instance\"} ${duration:-0}"

      echo "# HELP ${base}_last_run_timestamp_seconds Unix time the last run finished."
      echo "# TYPE ${base}_last_run_timestamp_seconds gauge"
      echo "${base}_last_run_timestamp_seconds{instance=\"$instance\"} $(date +%s)"

      if [[ "$status" != success ]]; then
         echo "# HELP ${base}_status Non-success status of the last run (info-style; 1 when present)."
         echo "# TYPE ${base}_status gauge"
         echo "${base}_status{instance=\"$instance\",status=\"$(_sdp_prom_label_escape "$status")\",error=\"$(_sdp_prom_label_escape "$error")\"} 1"
      fi

      # Numeric extras only -- a gauge value must be a number. Non-numeric
      # extras (e.g. a filename) are jsonl-only.
      local kv k v
      for kv in "$@"; do
         [[ "$kv" == *=* ]] || continue
         k=${kv%%=*}
         v=${kv#*=}
         if [[ "$v" =~ ^-?[0-9]+(\.[0-9]+)?$ ]]; then
            k=${k//[^a-zA-Z0-9_]/_}
            echo "${base}_${k}{instance=\"$instance\"} $v"
         fi
      done
   } > "$tmp" 2>/dev/null

   mv -f "$tmp" "$file" 2>/dev/null
}

# EXIT trap: remove this PID's own in-flight .prom temp file if the script
# died mid-write. This plus the opportunistic self-heal below is why no cron
# sweeper is needed (one was removed 2026-08-27; do not reinstate it):
# node_exporter's textfile collector only reads files ending literally in
# ".prom", so a leftover "<name>.prom.<pid>" is invisible to scraping either
# way -- this is disk hygiene, not a metrics-correctness fix.
function _sdp_prom_cleanup () {
   local dir="${SDP_METRICS_DIR:-/p4/metrics}"
   [[ -d "$dir" ]] || return 0
   local base
   base=$(_sdp_metric_base)
   rm -f "${dir}/${base}.prom.$$" 2>/dev/null
   # Opportunistic self-heal for a PRIOR run's stray temp (kill -9, OOM):
   # scoped to this exact script's own filename prefix (never another
   # script's temp) and to files older than a day (never a live sibling
   # process's in-flight temp, even under PID reuse).
   find "$dir" -maxdepth 1 -name "${base}.prom.[0-9]*" -mtime +1 -delete 2>/dev/null
   return 0
}

function _sdp_kill_log_mirror () {
   if [[ -n "${LOGTAIL_PID:-}" ]]; then
      sleep 0.3
      kill "$LOGTAIL_PID" 2>/dev/null
      LOGTAIL_PID=
   fi
}

function _sdp_emit_terminal_event () {
   local rc=${1:-0}
   [[ "${_SDP_EVENT_EMITTED:-0}" == 1 ]] && return 0
   _SDP_EVENT_EMITTED=1

   if [[ "${SDP_EVENT_STATUS:-success}" == success && "$rc" != 0 ]]; then
      SDP_EVENT_STATUS=failure
   fi

   local duration
   duration=$(sdp_elapsed)
   sdp_log_event "${SDP_EVENT_STATUS:-success}" "$rc" "$duration" "${SDP_EVENT_ERROR:-}" "${SDP_EVENT_EXTRA[@]+"${SDP_EVENT_EXTRA[@]}"}"
}

# Consolidated EXIT handler. Runs whether the script exits cleanly, via
# die(), via an unbound variable under set -u, via a set -e failure (through
# the ERR trap below setting status first), or via a signal (through
# _sdp_trap_signal's exit $((128+n)) below, which itself fires this).
# SIGKILL/OOM cannot be trapped by any shell -- documented limitation, not a
# gap here.
function _sdp_on_exit () {
   local rc=${1:-$?}
   if [[ -n "${SDP_SCRIPT_NAME:-}" ]]; then
      _sdp_emit_terminal_event "$rc"
      _sdp_prom_cleanup
   fi
   # Carries forward log_init()'s own interactive tail-mirror-kill behavior:
   # sdp_log_init's trap installation (above) runs after log_init's, so this
   # handler replaces log_init's inline EXIT trap for any script that calls
   # both (the documented calling order) -- this line is what keeps that
   # cleanup from being lost rather than a change to log_init itself.
   _sdp_kill_log_mirror
}

function _sdp_trap_err () {
   local rc=${1:-$?}
   sdp_set_status failure
   sdp_set_error "command failed (exit $rc): ${BASH_COMMAND:-unknown} at line ${BASH_LINENO[0]:-?}"
}

function _sdp_trap_signal () {
   local sig=$1
   local n=0
   case "$sig" in
      HUP)  n=1 ;;
      INT)  n=2 ;;
      TERM) n=15 ;;
   esac
   sdp_set_status failure
   sdp_set_error "received SIG$sig"
   # exit (rather than re-raising the real signal) is what makes this fire
   # the EXIT trap above -- the source of the "exactly once, however it
   # dies" guarantee for signals specifically.
   exit $(( 128 + n ))
}