DB-유

Bash Scripting: Error Handling and Logging

· linux, bash, scripting

Every ops script I've written started as a few commands pasted into a file. They work until cd /backup/$DATE fails on an empty variable and the next rm -rf * runs in the wrong place, or a dump fails silently and the script reports success for three months. Both have happened to me, or close to it. Bash can stop on errors, say where it stopped, and leave a trail. It just has to be the default.

This is the skeleton I put in every unattended script: strict mode, an error trap, logging to a file and syslog, a lock, and a cleanup handler.

Strict mode first

#!/usr/bin/env bash
set -Eeuo pipefail
IFS=$'\n\t'
  • -e exits when a command returns non-zero.
  • -u makes referencing an unset variable an error (so $DATE empty is caught).
  • -o pipefail makes a pipeline fail if any command in it fails, not just the last one. Without it, mysqldump db | gzip > dump.gz succeeds when mysqldump fails because gzip returned 0.
  • -E makes the ERR trap inherited by functions and subshells.
  • The IFS line stops word splitting on spaces, which prevents filenames with spaces from being split into multiple arguments.

-e is disabled inside if conditions, &&/|| lists and while tests, so if grep -q foo file; then still works.

Logging

I log to a file and syslog at once. The file is for reading a whole run; syslog is for central collection and journalctl:

SCRIPT_NAME=$(basename "$0")
LOG_FILE="/var/log/${SCRIPT_NAME%.sh}.log"

log() {
    local level=$1; shift
    local msg="$*"
    local ts
    ts=$(date '+%Y-%m-%d %H:%M:%S')
    printf '%s [%s] %s\n' "$ts" "$level" "$msg" | tee -a "$LOG_FILE" >&2
    logger -t "$SCRIPT_NAME" -p "user.${level,,}" -- "$msg"
}

log INFO "Starting $SCRIPT_NAME"

${level,,} lowercases the level so INFO becomes syslog priority user.info. Output goes to stderr so stdout stays clean if the script produces data.

An ERR trap

set -e alone kills the script without saying why. An ERR trap adds the line number and the command:

on_error() {
    local exit_code=$?
    local line_no=$1
    local cmd=$2
    log ERROR "Failed at line ${line_no}: '${cmd}' (exit ${exit_code})"
    exit "$exit_code"
}
trap 'on_error ${LINENO} "$BASH_COMMAND"' ERR

The result in the log is a line like 2019-10-26 02:30:04 [ERROR] Failed at line 42: 'mysqldump --single-transaction appdb' (exit 2), which is enough to fix most problems without re-running anything. That alone changed how I debug at 3 a.m.

Cleanup on EXIT

Temp files, lock files and mounted snapshots have to go whether the script succeeds or gets killed. EXIT fires in every case, including set -e failures and kill -TERM:

TMP_DIR=$(mktemp -d /tmp/${SCRIPT_NAME%.sh}.XXXXXX)

cleanup() {
    local exit_code=$?
    rm -rf "$TMP_DIR"
    if [ "$exit_code" -eq 0 ]; then
        log INFO "Finished successfully"
    else
        log ERROR "Finished with exit code ${exit_code}"
    fi
}
trap cleanup EXIT

cleanup reads $? first, so it can still report the real exit code even though it runs last.

One run at a time

A backup that takes longer than its interval will overlap the next run. Use flock on a file descriptor; the lock is released when the script exits:

LOCK_FILE="/var/lock/${SCRIPT_NAME%.sh}.lock"
exec 200>"$LOCK_FILE"
if ! flock -n 200; then
    log WARNING "Another instance is running, exiting"
    exit 0
fi

Exiting 0 is deliberate. A skipped run isn't something I want to be paged about.

All together

A small but complete backup script using everything above:

#!/usr/bin/env bash
set -Eeuo pipefail
IFS=$'\n\t'

SCRIPT_NAME=$(basename "$0")
LOG_FILE="/var/log/${SCRIPT_NAME%.sh}.log"
BACKUP_DIR="/backup/mysql"
DATE=$(date +%Y%m%d)

log()      { printf '%s [%s] %s\n' "$(date '+%F %T')" "$1" "${*:2}" | tee -a "$LOG_FILE" >&2; logger -t "$SCRIPT_NAME" -p "user.${1,,}" -- "${*:2}"; }
on_error() { log ERROR "Failed at line $1: '$2' (exit $?)"; }
cleanup()  { rm -rf "${TMP_DIR:-}"; log INFO "Exit code $?"; }
trap 'on_error ${LINENO} "$BASH_COMMAND"' ERR
trap cleanup EXIT

exec 200>"/var/lock/${SCRIPT_NAME%.sh}.lock"
flock -n 200 || { log WARNING "Already running"; exit 0; }

TMP_DIR=$(mktemp -d)
mkdir -p "$BACKUP_DIR"

log INFO "Dumping database"
mysqldump --single-transaction --routines appdb | gzip > "$TMP_DIR/appdb-$DATE.sql.gz"
mv "$TMP_DIR/appdb-$DATE.sql.gz" "$BACKUP_DIR/"

log INFO "Pruning dumps older than 14 days"
find "$BACKUP_DIR" -name 'appdb-*.sql.gz' -mtime +14 -delete

Writing to a temp directory and mv-ing into place at the end means a half-written dump never sits in $BACKUP_DIR looking like a good one.

Break it on purpose

I never trust an error handler I haven't seen fire. Force some failures:

bash -n backup.sh                       # syntax check only
sudo bash -x backup.sh                  # trace every command
sudo -u nobody bash backup.sh           # should fail on mkdir and log the line
tail -n 5 /var/log/backup.log
journalctl -t backup.sh --since today

Also run it twice concurrently (bash backup.sh & bash backup.sh) and confirm the second logs Already running.

Gotchas

  • line 12: DATE: unbound variable: set -u caught it. Default it with ${DATE:-$(date +%F)} or set it earlier.
  • The script exits with no message: a command failed inside a function and the ERR trap wasn't inherited. Add -E to the set line.
  • flock: 200: Bad file descriptor: exec 200>file failed, usually because /var/lock isn't writable by that user. Use /tmp or /run/user/$UID.
  • A for loop over $(ls) breaks on filenames with spaces even with IFS set. Don't parse ls; use a glob (for f in "$dir"/*) or find -print0 | while IFS= read -r -d '' f.
  • pipefail makes a grep in a pipeline fail the script when it finds nothing (exit 1). Append || true where "no match" is fine.

It's about fifteen extra lines per script. Worth it.