Shell Lesson 15 of 42

Logging Frameworks: syslog/journald, Structured Logs, Log Levels & Rotation — Making Your Scripts Observable

In Wave 1 we used printf '...' >&2 for messages and called it logging. That works for scripts that run in a terminal where you see the output. It does not work for scripts that:

Real logging answers all of those. This lesson covers:

By the end you’ll have a 100-line library that gives shell scripts logging features competitive with Python’s logging module.


1. The minimum-viable logger (recap from L13)

The simplest useful logger:

SCRIPT="${0##*/}"
info() { printf '[%s] INFO:  %s\n' "$SCRIPT" "$*" >&2; }
warn() { printf '[%s] WARN:  %s\n' "$SCRIPT" "$*" >&2; }
err()  { printf '[%s] ERROR: %s\n' "$SCRIPT" "$*" >&2; }
die()  { err "$@"; exit 1; }

Good for hour-old scripts. Production needs more.


2. Log levels with a threshold

Standard levels (from Python, syslog, most languages):

Level Numeric Use
DEBUG 10 Verbose, “what is happening” detail
INFO 20 Normal status messages
WARN 30 Something unexpected, but recoverable
ERROR 40 Failure, but script may continue
FATAL 50 Failure that exits the script

The script defines a threshold (LOG_LEVEL), and only messages at that level or higher actually print. Below threshold, they are silently discarded.

# default to INFO
LOG_LEVEL="${LOG_LEVEL:-INFO}"

declare -A _LEVELS=(
  [DEBUG]=10
  [INFO]=20
  [WARN]=30
  [ERROR]=40
  [FATAL]=50
)

_log() {
  local lvl=$1; shift
  local lvl_n=${_LEVELS[$lvl]:-20}
  local thr_n=${_LEVELS[$LOG_LEVEL]:-20}
  (( lvl_n >= thr_n )) || return 0
  printf '[%s] %-5s: %s\n' "$SCRIPT" "$lvl" "$*" >&2
}

debug() { _log DEBUG "$@"; }
info()  { _log INFO  "$@"; }
warn()  { _log WARN  "$@"; }
error() { _log ERROR "$@"; }
fatal() { _log FATAL "$@"; exit 1; }

Usage:

debug "starting parse phase"     # only shown if LOG_LEVEL=DEBUG
info  "parsed 100 records"
warn  "skipping malformed line 42"
error "failed to upload to s3"
fatal "out of disk; aborting"

# Run with DEBUG visibility:
LOG_LEVEL=DEBUG ./script

This pattern alone gets you 80% of “real logging.” The rest is destinations, format, rotation.

Why associative array for levels?

_LEVELS[$lvl] is O(1) lookup. We could also use a case statement:

case "$lvl" in
  DEBUG) lvl_n=10 ;;
  INFO)  lvl_n=20 ;;
  WARN)  lvl_n=30 ;;
  ERROR) lvl_n=40 ;;
  FATAL) lvl_n=50 ;;
esac

Either works. Associative-array is cleaner but requires bash 4+. For scripts that must run on macOS stock bash 3.2, use the case form.

Numeric level threshold

If your CI sets LOG_LEVEL=2 instead of LOG_LEVEL=INFO, support both:

_log() {
  local lvl=$1; shift
  local lvl_n=${_LEVELS[$lvl]:-20}
  local thr_n
  if [[ "$LOG_LEVEL" =~ ^[0-9]+$ ]]; then
    thr_n="$LOG_LEVEL"
  else
    thr_n=${_LEVELS[$LOG_LEVEL]:-20}
  fi
  (( lvl_n >= thr_n )) || return 0
  printf '[%s] %-5s: %s\n' "$SCRIPT" "$lvl" "$*" >&2
}

3. Timestamp every line

Almost always you want timestamps. ISO 8601 is the standard:

ts() { date '+%Y-%m-%dT%H:%M:%S%z'; }

_log() {
  local lvl=$1; shift
  ...
  printf '%s [%s] %-5s: %s\n' "$(ts)" "$SCRIPT" "$lvl" "$*" >&2
}

Output:

2026-06-22T14:35:12+0000 [deploy.sh] INFO : starting deploy
2026-06-22T14:35:13+0000 [deploy.sh] WARN : skipping malformed entry

Use UTC timestamps in production (date -u):

ts() { date -u '+%Y-%m-%dT%H:%M:%SZ'; }

UTC avoids the daylight-saving-time mess and matches what every log aggregator wants. The trailing Z literally means UTC.

Microsecond precision

For high-frequency logging:

ts() { date -u '+%Y-%m-%dT%H:%M:%S.%6NZ'; }

%6N is microseconds (BSD date uses %N for nanoseconds; truncate to 6 digits for microseconds). On macOS stock date, this might not work — install coreutils (brew install coreutils) and use gdate.


4. Multiple destinations: stderr + file + journald

Real scripts log to multiple places. The clean way: a single _emit function that writes to all configured handlers.

LOG_FILE="${LOG_FILE:-}"             # optional path
LOG_TO_SYSLOG="${LOG_TO_SYSLOG:-0}"  # 1 to also log to journald/syslog
LOG_TO_STDERR="${LOG_TO_STDERR:-1}"  # 1 to log to stderr (default on)

_emit() {
  local line=$1
  [[ "$LOG_TO_STDERR" == 1 ]] && printf '%s\n' "$line" >&2
  [[ -n "$LOG_FILE" ]] && printf '%s\n' "$line" >> "$LOG_FILE"
  if [[ "$LOG_TO_SYSLOG" == 1 ]]; then
    logger -t "$SCRIPT" -- "$line"      # POSIX syslog client
  fi
}

_log() {
  local lvl=$1; shift
  local lvl_n=${_LEVELS[$lvl]:-20}
  local thr_n=${_LEVELS[$LOG_LEVEL]:-20}
  (( lvl_n >= thr_n )) || return 0
  _emit "$(printf '%s [%s] %-5s: %s' "$(ts)" "$SCRIPT" "$lvl" "$*")"
}

Now:

# Just stderr (default)
./script

# Also to file
LOG_FILE=/var/log/myscript.log ./script

# Also to syslog
LOG_TO_SYSLOG=1 ./script

# Quiet stderr, only file
LOG_TO_STDERR=0 LOG_FILE=/var/log/x.log ./script

logger is the POSIX syslog client, present on every Linux system and macOS. By default it sends to local syslog (which on modern Linux is journald). View with:

journalctl -t myscript        # filter by tag (-t)
sudo tail -f /var/log/syslog  # raw

systemd-cat — alternative to logger

On systemd systems:

echo "this is a log line" | systemd-cat -t myscript -p info

systemd-cat writes directly to journald with full priority awareness:

_emit() {
  local line=$1 lvl=$2
  [[ "$LOG_TO_STDERR" == 1 ]] && printf '%s\n' "$line" >&2
  [[ -n "$LOG_FILE" ]] && printf '%s\n' "$line" >> "$LOG_FILE"
  if [[ "$LOG_TO_JOURNAL" == 1 ]] && command -v systemd-cat >/dev/null; then
    printf '%s\n' "$line" | systemd-cat -t "$SCRIPT" -p "$(_priority "$lvl")"
  fi
}

_priority() {
  case "$1" in
    DEBUG) echo "debug" ;;
    INFO)  echo "info" ;;
    WARN)  echo "warning" ;;
    ERROR) echo "err" ;;
    FATAL) echo "crit" ;;
    *)     echo "info" ;;
  esac
}

The journald priorities follow syslog conventions (emerg, alert, crit, err, warning, notice, info, debug).

logger -p — set syslog facility/priority

logger -p user.info "$line"      # facility=user, priority=info
logger -p user.err "$line"       # priority=err
logger -p local0.warn "$line"    # facility=local0 (1-7 reserved for app use)

Map your script’s level to a syslog priority:

_syslog_pri() {
  case "$1" in
    DEBUG) echo "debug" ;;
    INFO)  echo "info" ;;
    WARN)  echo "warning" ;;
    ERROR) echo "err" ;;
    FATAL) echo "crit" ;;
    *)     echo "info" ;;
  esac
}

This lets journalctl --priority=err correctly filter your script’s errors.


5. Structured logging — key=value and JSON

Plain text is fine for humans but bad for machines. Log aggregators (Loki, Splunk, ES, Datadog) parse logs into fields. Two common structured formats:

Logfmt (key=value)

Heroku-style. Easy to read for humans, parseable by machines.

2026-06-22T14:35:12Z level=info script=deploy.sh msg="starting deploy" env=prod tag=v1.2.3

Generate with:

log_kv() {
  local lvl=$1; shift
  local kvs=""
  while [[ $# -gt 0 ]]; do
    local key=${1%%=*}            # everything before first =
    local val=${1#*=}             # everything after first =
    # Quote if value contains space or special char
    if [[ "$val" =~ [[:space:]\"\\] ]]; then
      val=\"${val//\"/\\\"}\"
    fi
    kvs+=" $key=$val"
    shift
  done
  printf '%s level=%s script=%s%s\n' "$(ts)" "${lvl,,}" "$SCRIPT" "$kvs" >&2
}

log_kv INFO msg="starting deploy" env=prod tag=v1.2.3 user="$USER"

${lvl,,} is “lowercase the value” (bash 4+). For older bash use tr:

"$(printf '%s' "$lvl" | tr '[:upper:]' '[:lower:]')"

JSON

For structured-by-default output:

2026-06-22T14:35:12Z {"level":"info","script":"deploy.sh","msg":"starting deploy","env":"prod","tag":"v1.2.3"}

Build with jq:

log_json() {
  local lvl=$1; shift
  jq -cn --arg ts "$(ts)" --arg lvl "${lvl,,}" --arg script "$SCRIPT" \
        --arg msg "$1" --argjson kv "$(_make_kv_obj "${@:2}")" \
        '{ts: $ts, level: $lvl, script: $script, msg: $msg} + $kv' >&2
}

_make_kv_obj() {
  if [[ $# -eq 0 ]]; then echo "{}"; return; fi
  local out="{"
  while [[ $# -gt 0 ]]; do
    local key=${1%%=*} val=${1#*=}
    out+="\"$key\": $(jq -Rn --arg v "$val" '$v'), "
    shift
  done
  out=${out%, }      # strip trailing comma+space
  out+="}"
  echo "$out"
}

log_json INFO "starting deploy" env=prod tag=v1.2.3 user="$USER"

This is more involved. For most scripts, logfmt is plenty.

Picking a format at runtime

LOG_FORMAT="${LOG_FORMAT:-text}"   # text|kv|json

_render() {
  local lvl=$1 msg=$2
  shift 2
  case "$LOG_FORMAT" in
    text) printf '%s [%s] %-5s: %s\n' "$(ts)" "$SCRIPT" "$lvl" "$msg" ;;
    kv)   _logfmt_render "$lvl" "$msg" "$@" ;;
    json) _json_render "$lvl" "$msg" "$@" ;;
  esac
}

Now CI sets LOG_FORMAT=json and the platform team’s collector parses it; humans run with default text. Same script, two consumers.


6. Log rotation

If your script writes to a file, that file grows forever. Use logrotate:

/etc/logrotate.d/myscript

/var/log/myscript.log {
    daily
    rotate 14
    compress
    delaycompress
    missingok
    notifempty
    create 0644 myscript myscript
    postrotate
        # if your script keeps a long-running file handle, signal it
        # systemctl kill -s USR1 myscript.service 2>/dev/null || true
    endscript
}

Drop this file into /etc/logrotate.d/. The cron job /etc/cron.daily/logrotate (or systemd timer) runs logrotate /etc/logrotate.conf daily, processing every file in /etc/logrotate.d/.

Fields:

For shell scripts that just append-and-close every line, no postrotate is needed.

Manual rotation in-script (without logrotate)

Sometimes you can’t install logrotate (containers, CI). Roll your own:

LOG_FILE="/var/log/myscript.log"
MAX_SIZE=$((10 * 1024 * 1024))    # 10 MB

rotate_if_big() {
  [[ -f "$LOG_FILE" ]] || return 0
  local size
  size=$(wc -c < "$LOG_FILE")
  if (( size > MAX_SIZE )); then
    mv -- "$LOG_FILE" "${LOG_FILE}.$(date -u +%Y%m%dT%H%M%SZ)"
    : > "$LOG_FILE"
  fi
}

Call rotate_if_big periodically (or before logging). For more complex schemes (keep N rolled files, compress old ones), use logrotate proper.


7. Reading journald logs

For scripts that log to journald via logger or systemd-cat, retrieval is via journalctl:

# All entries from "myscript" tag
journalctl -t myscript

# Last 100 lines
journalctl -t myscript -n 100

# Follow live
journalctl -t myscript -f

# Filter by priority (errors and worse)
journalctl -t myscript -p err

# Time range
journalctl -t myscript --since="1 hour ago"
journalctl -t myscript --since="2026-06-22 09:00:00" --until="2026-06-22 10:00:00"

# As JSON (for piping into jq)
journalctl -t myscript -o json | jq '.MESSAGE'

# Just the message field, plain text
journalctl -t myscript -o cat

# Specific systemd unit (if your script runs as one)
journalctl -u myscript.service

Combined:

# Show errors from the last hour, just the messages
journalctl -t myscript -p err --since="1 hour ago" -o cat

8. The canonical lib/log.sh

Putting everything together:

# lib/log.sh — production-grade shell logging
# Source from any script: source "$(dirname "${BASH_SOURCE[0]}")/lib/log.sh"
#
# Configurable via environment variables:
#   LOG_LEVEL      DEBUG|INFO|WARN|ERROR|FATAL  (default: INFO)
#   LOG_FILE       path or empty                (default: empty = no file)
#   LOG_FORMAT     text|kv|json                 (default: text)
#   LOG_TO_STDERR  0 or 1                       (default: 1)
#   LOG_TO_SYSLOG  0 or 1                       (default: 0)
#
# Use: debug, info, warn, error, fatal — they take a message and optional key=value pairs
#   info "starting deploy" env=prod tag=v1.2.3

readonly LOG_SCRIPT_NAME="${0##*/}"
readonly LOG_HOSTNAME="$(hostname -s 2>/dev/null || echo unknown)"
declare -A _LOG_LEVELS=( [DEBUG]=10 [INFO]=20 [WARN]=30 [ERROR]=40 [FATAL]=50 )

LOG_LEVEL="${LOG_LEVEL:-INFO}"
LOG_FILE="${LOG_FILE:-}"
LOG_FORMAT="${LOG_FORMAT:-text}"
LOG_TO_STDERR="${LOG_TO_STDERR:-1}"
LOG_TO_SYSLOG="${LOG_TO_SYSLOG:-0}"

_log_ts() { date -u '+%Y-%m-%dT%H:%M:%SZ'; }

_log_threshold_n() {
  local v=${LOG_LEVEL^^}
  echo "${_LOG_LEVELS[$v]:-20}"
}

_log_pri() {
  case "$1" in
    DEBUG) echo debug ;;
    INFO) echo info ;;
    WARN) echo warning ;;
    ERROR) echo err ;;
    FATAL) echo crit ;;
    *) echo info ;;
  esac
}

_log_render_text() {
  local lvl=$1 msg=$2
  shift 2
  local extras=""
  if [[ $# -gt 0 ]]; then extras=" $*"; fi
  printf '%s [%s] %-5s: %s%s' "$(_log_ts)" "$LOG_SCRIPT_NAME" "$lvl" "$msg" "$extras"
}

_log_render_kv() {
  local lvl=$1 msg=$2
  shift 2
  local extras=""
  while [[ $# -gt 0 ]]; do
    local k=${1%%=*} v=${1#*=}
    if [[ "$v" =~ [[:space:]\"\\] ]]; then
      v="\"${v//\"/\\\"}\""
    fi
    extras+=" $k=$v"
    shift
  done
  printf '%s level=%s script=%s host=%s msg=%q%s' "$(_log_ts)" "${lvl,,}" "$LOG_SCRIPT_NAME" "$LOG_HOSTNAME" "$msg" "$extras"
}

_log_emit() {
  local lvl=$1; shift
  local rendered
  case "$LOG_FORMAT" in
    kv)   rendered=$(_log_render_kv "$lvl" "$@") ;;
    json) rendered=$(_log_render_kv "$lvl" "$@") ;;   # keep simple; full JSON omitted in this lib
    text|*) rendered=$(_log_render_text "$lvl" "$@") ;;
  esac
  [[ "$LOG_TO_STDERR" == 1 ]] && printf '%s\n' "$rendered" >&2
  if [[ -n "$LOG_FILE" ]]; then
    printf '%s\n' "$rendered" >> "$LOG_FILE"
  fi
  if [[ "$LOG_TO_SYSLOG" == 1 ]]; then
    logger -t "$LOG_SCRIPT_NAME" -p "user.$(_log_pri "$lvl")" -- "$rendered" 2>/dev/null || true
  fi
}

_log() {
  local lvl=$1; shift
  local lvl_n=${_LOG_LEVELS[${lvl^^}]:-20}
  local thr_n
  thr_n=$(_log_threshold_n)
  (( lvl_n >= thr_n )) || return 0
  _log_emit "$lvl" "$@"
}

debug() { _log DEBUG "$@"; }
info()  { _log INFO  "$@"; }
warn()  { _log WARN  "$@"; }
error() { _log ERROR "$@"; }
fatal() { _log FATAL "$@"; exit 1; }

Usage:

#!/usr/bin/env bash
set -Eeuo pipefail
source "$(dirname "${BASH_SOURCE[0]}")/lib/log.sh"

info "starting deploy" env=prod tag=v1.2.3
debug "kubeconfig at $KUBECONFIG"
warn "no rollback plan defined; proceeding anyway"
error "rollout failed"
fatal "out of disk; aborting"

Run:

./script                                          # default INFO+ to stderr
LOG_LEVEL=DEBUG ./script                          # everything visible
LOG_FORMAT=kv ./script                            # logfmt-style
LOG_FILE=/var/log/myscript.log ./script           # also to file
LOG_TO_SYSLOG=1 ./script                          # also to syslog
LOG_LEVEL=ERROR ./script                          # only errors and fatals

This is competitive with what serious shell projects ship.


9. Patterns for production usage

Capture command output and log it

run() {
  local lvl=${1:-INFO}; shift
  info "running: $*"
  local out
  if ! out=$("$@" 2>&1); then
    error "command failed (exit $?): $*"
    error "output: $out"
    return 1
  fi
  debug "output: $out"
}

# Use:
run INFO kubectl apply -f deploy.yaml
run INFO docker pull ghcr.io/myorg/api:v1.2.3

This wraps every command with logging — entry, exit code, full output.

Time how long a step took

time_step() {
  local label=$1; shift
  local start
  start=$(date +%s)
  "$@"
  local rc=$?
  local end
  end=$(date +%s)
  local elapsed=$((end - start))
  if [[ $rc -eq 0 ]]; then
    info "step done: $label" duration_s=$elapsed
  else
    error "step failed: $label" duration_s=$elapsed exit_code=$rc
  fi
  return $rc
}

# Use:
time_step "image pull" docker pull ghcr.io/myorg/api:v1.2.3
time_step "kubectl apply" kubectl apply -f deploy.yaml

Correlation IDs

When a script kicks off other commands, attach a correlation ID:

CORRELATION_ID="${CORRELATION_ID:-$(uuidgen 2>/dev/null || echo "$$-$(date +%s)")}"
export CORRELATION_ID

info "starting deploy" cid=$CORRELATION_ID env=$ENV tag=$TAG

Now grep across logs by cid=... and you have the full trace of one script invocation across multiple processes.

Mute external command stderr but log on failure

run_quiet() {
  local out
  if ! out=$("$@" 2>&1); then
    error "command failed: $*" exit_code=$?
    error "$out"
    return 1
  fi
}

Don’t pollute stderr with chatty commands; only log if they actually fail.


10. Common pitfalls

Buffered stderr in CI

If your CI runs your script with stdout/stderr captured to a log, you may see no output until the script exits — because libc buffers stderr for non-tty output. Fix:

exec 2> >(stdbuf -oL cat >&2)             # line-buffered stderr

Or simply stdbuf -oL ./script from the CI runner.

Logging from background subshells

When you cmd & for parallelism, those subshells inherit LOG_FILE. If two write to the same file simultaneously, lines may interleave at the byte level. Either:

Locale-sensitive date

date formats may differ by locale. For consistency in logs, always set:

TZ=UTC LC_ALL=C date '+%Y-%m-%dT%H:%M:%SZ'

Or stamp via printf '%(...)T' (bash 4.2+):

ts() { printf '%(%Y-%m-%dT%H:%M:%SZ)T\n' -1 ; }   # -1 = current time, no fork

The bash builtin avoids the date fork entirely — much faster in tight loops.

logger not present

On minimal containers (scratch, busybox-without-syslogtools), logger isn’t there. Detect:

if command -v logger >/dev/null 2>&1; then
  logger -t "$SCRIPT" -- "$line"
fi

Fall back to file or stderr if absent.

Forgetting to flush

echo "important message" > "$LOG_FILE"   # bash always flushes after a builtin

Bash’s echo/printf flush after each invocation. But if you redirect a long-running tail -f style command, watch for buffering. stdbuf -oL and unbuffer are your friends.

Logging passwords / secrets

A FATAL bug: logging kubectl output that contains tokens, or curl -v output that contains Authorization headers. Always sanitise:

sanitize() {
  sed -E 's/(Authorization|password|token)[:=][^[:space:]]*/\1=REDACTED/g'
}

run kubectl get secrets -o yaml | sanitize | tee >(info)

Or capture and grep:

out=$(curl -v "$URL" 2>&1)
out=$(sed -E 's/(Bearer )[A-Za-z0-9._-]+/\1REDACTED/g' <<<"$out")
debug "$out"

The single highest-impact thing you can do for log hygiene.


11. Twelve idioms for daily use

# 1. Minimum logger
info() { printf '[%s] INFO: %s\n' "${0##*/}" "$*" >&2; }

# 2. Source canonical lib/log.sh
source "$(dirname "${BASH_SOURCE[0]}")/lib/log.sh"

# 3. ISO 8601 UTC timestamp
ts() { date -u '+%Y-%m-%dT%H:%M:%SZ'; }

# 4. Bash-builtin timestamp (no fork)
ts() { printf '%(%Y-%m-%dT%H:%M:%SZ)T\n' -1; }

# 5. Level threshold at runtime
LOG_LEVEL=DEBUG ./script

# 6. Log to syslog/journald
LOG_TO_SYSLOG=1 ./script
journalctl -t myscript -f

# 7. Logger one-liner
logger -t myscript "hello world"

# 8. JSON output via jq (one-line)
jq -cn --arg ts "$(ts)" --arg msg "$msg" '{ts: $ts, msg: $msg}'

# 9. logfmt key=value pair
printf 'level=%s msg=%q env=%s tag=%s\n' "$lvl" "$msg" "$ENV" "$TAG"

# 10. Sanitize secrets before logging
sed -E 's/(token|password|Authorization)[:=][^[:space:]]+/\1=REDACTED/g'

# 11. Logrotate config (one-liner test)
logrotate -d /etc/logrotate.d/myscript    # dry-run

# 12. Atomic file rotation
mv "$LOG_FILE" "$LOG_FILE.$(date -u +%Y%m%dT%H%M%SZ)" && : > "$LOG_FILE"

12. What you must internalise before lesson 16


What’s next

Lesson 16: Concurrency — Backgrounding, GNU parallel, xargs -P, FIFOs & flock. We’ve used & and wait casually. Now we cover real concurrency: parallel job pools with xargs -P, GNU parallel for declarative parallelism, FIFOs (named pipes) for inter-process communication, and flock for cross-script mutual exclusion. After L16 your scripts will use all your cores — without race conditions.

See you there.

shellbashloggingsyslogjournaldstructured-loggingobservabilitylog-levelslogrotateproduction
Need this built for real?

Vinod is a Senior Cloud Architect (22+ yrs) — available for Azure / AWS / GCP architecture, landing zones, and migrations.

Work with me

Comments