Logging & Errors

11.4. Logging & Errors#

11.4.1. Common Pitfalls#

1. Mixing stdout and stderr unintentionally

# Bad: Loses stderr
output=$(command)  # stderr goes to console
echo "$output"     # Only stdout captured

# Good: Capture both when needed
output=$(command 2>&1)  # Both in $output
# or separate them
output=$(command 2>/tmp/err.log)
errors=$(cat /tmp/err.log)

2. Log files filling up disk

# Bad: No rotation, grows indefinitely
echo "Log entry" >> /var/log/app.log

# Good: Implement rotation
# Add to crontab:
# @daily /usr/local/bin/rotate_logs /var/log/app.log

# Or use logrotate configuration in /etc/logrotate.d/

3. Not preserving error context

# Bad: Error context lost
command || echo "Error"

# Better: Save context
if ! output=$(command 2>&1); then
  echo "Command failed with code $?" >&2
  echo "Output was: $output" >&2
  exit 1
fi

4. Forgetting logs need privileges

# Bad: Script can't write to /var/log/ if not root
echo "Error" >> /var/log/app.log

# Better: Use appropriate location
LOG_DIR="${LOG_DIR:-.}"  # Current dir as fallback
mkdir -p "$LOG_DIR"
echo "Error" >> "$LOG_DIR/app.log"

11.4.2. Real-World Example: Comprehensive Logging System#

#!/bin/bash
set -euo pipefail

# APPLICATION LOGGING SYSTEM
readonly APP_NAME="backup_system"
readonly LOG_DIR="/var/log/$APP_NAME"
readonly LOG_FILE="$LOG_DIR/$APP_NAME.log"
readonly ERROR_LOG="$LOG_DIR/error.log"

# Initialize logging
initialize_logging() {
  mkdir -p "$LOG_DIR" || {
    echo "Failed to create log directory" >&2
    return 1
  }
}

# Log function with level
log() {
  local level=$1
  shift
  local message="$@"
  local timestamp=$(date '+%Y-%m-%d %H:%M:%S')
  
  echo "[$timestamp] [$level] $message" >> "$LOG_FILE"
  
  # Also log errors to separate file
  if [[ "$level" == "ERROR" ]]; then
    echo "[$timestamp] $message" >> "$ERROR_LOG"
  fi
}

# Error handler
handle_error() {
  local line=$1
  local exit_code=$2
  
  log "ERROR" "Command failed at line $line (exit code: $exit_code)"
  log "ERROR" "Failed command: $BASH_COMMAND"
  
  # Alert admin for critical errors
  if [[ $exit_code -gt 10 ]]; then
    {
      echo "Critical Error in $APP_NAME"
      echo "Line: $line"
      echo "Exit Code: $exit_code"
      echo "Command: $BASH_COMMAND"
      echo ""
      echo "Recent logs:"
      tail -10 "$ERROR_LOG"
    } | mail -s "CRITICAL: $APP_NAME failed" admin@example.com
  fi
}

trap 'handle_error $LINENO $?' ERR

# Initialize and run
initialize_logging || exit 1
log "INFO" "$APP_NAME starting"

# Do work
log "INFO" "Backup process started"
perform_backup || log "ERROR" "Backup failed"
log "INFO" "$APP_NAME completed"

# Rotate logs if needed
[[ -f "$LOG_FILE" ]] && [[ $(stat -c%s "$LOG_FILE" 2>/dev/null || echo 0) -gt 1048576 ]] && {
  gzip "$LOG_FILE"
  > "$LOG_FILE"
}

11.4.3. Error Redirection Patterns#

11.4.3.1. Separating stdout and stderr#

#!/bin/bash

# Different destinations
command > stdout.log 2> stderr.log

# stdout to file, stderr to console
command > output.log

# stderr to file, stdout to console
command 2> error.log

# Both to file
command > all.log 2>&1

# Stderr to specific location
command 2>/var/log/errors.log

# Append instead of overwrite
command >> output.log 2>&1

11.4.3.2. Conditional Error Handling#

# Capture error output
output=$(command 2>&1) || {
  exit_code=$?
  echo "Command failed with code $exit_code" >&2
  echo "Output: $output" >&2
  exit $exit_code
}

# Discard expected errors
grep pattern file.txt 2>/dev/null || {
  # Pattern not found (expected when using grep as a condition)
  echo "Pattern not found, continuing..."
}

11.4.3.3. Tee for Dual Output#

# Log to file AND display on console
command 2>&1 | tee -a /var/log/app.log

# Append to log while showing errors
command 2>&1 | tee -a /var/log/app.log >&2

# Color output to console, plain to log
command 2>&1 | tee >(cat >> /var/log/plain.log)

11.4.4. Log Levels and Filtering#

11.4.4.1. Standard Log Levels#

# Implement log levels with filtering
declare -r LOG_LEVEL_DEBUG=0
declare -r LOG_LEVEL_INFO=1
declare -r LOG_LEVEL_WARN=2
declare -r LOG_LEVEL_ERROR=3

declare -r CURRENT_LOG_LEVEL=$LOG_LEVEL_INFO

log() {
  local level=$1
  shift
  local message="$@"
  
  # Only log if level meets threshold
  [[ $level -lt $CURRENT_LOG_LEVEL ]] && return 0
  
  case $level in
    0) level_str="DEBUG";;
    1) level_str="INFO";;
    2) level_str="WARN";;
    3) level_str="ERROR";;
  esac
  
  echo "[$(date '+%H:%M:%S')] $level_str: $message"
}

# Usage
log $LOG_LEVEL_DEBUG "Entering function"  # Not shown (below threshold)
log $LOG_LEVEL_INFO "Processing file"     # Shown
log $LOG_LEVEL_ERROR "Operation failed"   # Shown

11.4.4.2. Log Rotation#

#!/bin/bash

rotate_logs() {
  local log_file=$1
  local max_size=${2:-10485760}  # 10MB default
  
  if [[ -f "$log_file" && $(stat -f%z "$log_file" 2>/dev/null || stat -c%s "$log_file") -gt $max_size ]]; then
    # Compress and archive
    gzip -c "$log_file" > "${log_file}.$(date +%Y%m%d_%H%M%S).gz"
    
    # Truncate original
    > "$log_file"
    
    # Remove old archives (keep 7 days)
    find $(dirname "$log_file") -name "$(basename $log_file).*.gz" -mtime +7 -delete
  fi
}

# Run periodically from cron
# @hourly /usr/local/bin/rotate_logs /var/log/app.log

11.4.5. Structured Logging#

Create consistent, parseable logs for debugging and monitoring:

11.4.5.1. Basic Log Format#

#!/bin/bash

log() {
  local level=$1
  shift
  local message="$@"
  
  # ISO 8601 timestamp
  local timestamp=$(date -u +"%Y-%m-%dT%H:%M:%SZ")
  
  # Log format: [TIMESTAMP] LEVEL MESSAGE
  echo "[$timestamp] $level: $message" >> /var/log/app.log
}

# Usage
log "INFO" "Application started"
log "WARN" "Low memory detected"
log "ERROR" "Failed to connect to database"

11.4.5.2. Structured JSON Logging#

log_json() {
  local level=$1
  local message=$2
  local context=$3
  
  printf '{"timestamp":"%s","level":"%s","message":"%s","context":"%s"}\n' \
    "$(date -u +"%Y-%m-%dT%H:%M:%SZ")" \
    "$level" \
    "$message" \
    "$context" >> /var/log/app.json.log
}

# Usage (parseable by tools like jq)
log_json "ERROR" "Database connection failed" "host=db1.example.com"

11.4.5.3. Syslog Integration#

#!/bin/bash

# Send to system syslog
logger -t myscript "Application started"
logger -t myscript -p user.error "Critical error occurred"
logger -t myscript -p user.info "Backup completed successfully"

# View logs
tail -f /var/log/syslog | grep myscript
Contents