Structured Logging, Timestamps, and Verbosity Levels

1. Logs are an operational interface

A production log should help a human or system reconstruct what happened without reading the source code. Useful logs identify time, severity, operation, resource context, and outcome.

flowchart LR
  E["event"] --> F["format"]
  F --> S["stderr / log sink"]
  S --> O["operator / collector"]

2. Send logs to stderr and results to stdout

printf 'artifact-123\n'

printf 'level=INFO msg=%q service=%q\n' \
  'upload complete' "$service" >&2

This lets scripts be composed: stdout can remain machine-readable while diagnostic output remains visible.

3. Add timestamps at the logging boundary

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

printf 'ts=%s level=INFO msg=%q\n' \
  "$(timestamp)" 'deployment started' >&2

UTC timestamps simplify correlation across machines. If sub-second precision matters, verify the date implementation available on your platforms.

4. Define severity levels consistently

5. Centralize formatting in a log function

LOG_LEVEL=${LOG_LEVEL:-INFO}

log() {
  local level=$1
  shift

  printf 'ts=%s level=%s msg=%q\n' \
    "$(date -u '+%Y-%m-%dT%H:%M:%SZ')" \
    "$level" \
    "$*" >&2
}

log INFO "starting deploy service=$service"

One helper prevents every call site from inventing a different timestamp or severity format.

6. Verbosity should change detail, not correctness

verbose=${VERBOSE:-false}

debug() {
  [[ $verbose == true ]] || return 0
  log DEBUG "$*"
}

Turning debug logging off must not suppress necessary validation, status checks, or cleanup.

7. Key-value logs are easier to search than prose-only logs

printf 'ts=%s level=INFO event=deploy service=%q env=%q status=success\n' \
  "$(date -u '+%Y-%m-%dT%H:%M:%SZ')" \
  "$service" \
  "$environment" >&2

Simple stable keys can be enough for shell scripts. If your logging backend expects JSON, generate valid JSON with a JSON-aware tool rather than hand-escaping arbitrary strings.

8. Never treat secrets as ordinary context

printf 'level=INFO auth=present endpoint=%q\n' "$endpoint" >&2
# Do not log: token=$API_TOKEN

9. Correlation IDs connect events from one run

run_id=${RUN_ID:-"bash-$$-$(date +%s)"}
log INFO "run_id=$run_id event=start"

A run or request identifier helps correlate retries, remote operations, and cleanup messages from the same invocation.

10. Record duration around slow operations

start=$SECONDS

if perform_deploy; then
  status=0
else
  status=$?
fi

elapsed=$((SECONDS - start))
log INFO "event=deploy_done status=$status duration_s=$elapsed"

11. Hands-on lab: structured logger

mkdir -p "$HOME/devops-academy/bash/chapter12/lesson03"
cd "$HOME/devops-academy/bash/chapter12/lesson03"

cat > logger-demo.sh <<'EOF'
#!/usr/bin/env bash
set -u

LOG_LEVEL=${LOG_LEVEL:-INFO}
RUN_ID=${RUN_ID:-"run-$$"}

level_value() {
  case $1 in
    DEBUG) printf '10\n' ;;
    INFO)  printf '20\n' ;;
    WARN)  printf '30\n' ;;
    ERROR) printf '40\n' ;;
    *)     printf '20\n' ;;
  esac
}

log() {
  local level=$1
  shift

  local current wanted
  current=$(level_value "$LOG_LEVEL")
  wanted=$(level_value "$level")
  (( wanted >= current )) || return 0

  printf 'ts=%s level=%s run_id=%q msg=%q\n' \
    "$(date -u '+%Y-%m-%dT%H:%M:%SZ')" \
    "$level" \
    "$RUN_ID" \
    "$*" >&2
}

log DEBUG "debug detail"
log INFO "deployment started"
log WARN "retrying endpoint"
log ERROR "example failure diagnostic"
EOF

bash logger-demo.sh
LOG_LEVEL=DEBUG bash logger-demo.sh

12. Knowledge check

13. Summary

Production Bash logging should be structured enough to search, consistent enough to correlate, and disciplined enough to keep stdout clean and secrets hidden. Centralize format, timestamps, levels, run IDs, and duration reporting.

14. Further reading

• GNU Bash Reference Manual — printf and special parameters.
• POSIX standard streams.
• OpenTelemetry logging data model concepts.
• OWASP Logging Cheat Sheet — sensitive data and event design.