Logging

Good logging transforms debugging from guesswork into detective work. Scripts that silently do their job are great—until something goes wrong. This lesson teaches you to implement professional logging that helps you understand exactly what your script did, when, and why it failed!

Basic Logging Functions

Start with simple logging functions that add timestamps and identify message types.

Click Run to execute your code

Essential Logging Functions

# Timestamp function
timestamp() {
    date '+%Y-%m-%d %H:%M:%S'
}

# Basic log function
log() {
    echo "[$(timestamp)] $*"
}

# Error logging (to stderr)
log_error() {
    echo "[$(timestamp)] ERROR: $*" >&2
}

# Warning logging
log_warn() {
    echo "[$(timestamp)] WARN: $*" >&2
}

# Info logging
log_info() {
    echo "[$(timestamp)] INFO: $*"
}

# Debug logging (controlled by variable)
log_debug() {
    [[ "${DEBUG:-false}" == "true" ]] && echo "[$(timestamp)] DEBUG: $*"
}

Implementing Log Levels

Log levels let you control verbosity without changing code.

Click Run to execute your code

Standard Log Levels

Logging to Files

For long-running scripts and services, log to files for later analysis.

# Setup log file
LOG_FILE="${LOG_FILE:-/var/log/myapp/app.log}"
LOG_DIR="$(dirname "$LOG_FILE")"

# Ensure log directory exists
setup_logging() {
    mkdir -p "$LOG_DIR" || {
        echo "Cannot create log directory: $LOG_DIR" >&2
        exit 1
    }

    # Test write access
    touch "$LOG_FILE" || {
        echo "Cannot write to log file: $LOG_FILE" >&2
        exit 1
    }
}

# Log to both file and stdout
log() {
    local message="[$(date '+%Y-%m-%d %H:%M:%S')] [$$] $*"
    echo "$message" | tee -a "$LOG_FILE"
}

# Log only to file (silent mode)
log_quiet() {
    echo "[$(date '+%Y-%m-%d %H:%M:%S')] [$$] $*" >> "$LOG_FILE"
}

# Redirect all output to log file
exec_with_logging() {
    exec > >(tee -a "$LOG_FILE") 2>&1
}

# Log with rotation (simple)
rotate_log() {
    local max_size=${1:-10485760}  # 10MB default

    if [[ -f "$LOG_FILE" ]]; then
        local size=$(stat -f%z "$LOG_FILE" 2>/dev/null || stat -c%s "$LOG_FILE")
        if [[ $size -gt $max_size ]]; then
            mv "$LOG_FILE" "$LOG_FILE.$(date +%Y%m%d%H%M%S)"
            touch "$LOG_FILE"
            log "Log rotated"
        fi
    fi
}

Structured Logging

For scripts that integrate with log aggregators, use structured formats like JSON.

# JSON logging
log_json() {
    local level="$1"
    local message="$2"
    shift 2

    # Build extra fields
    local extra=""
    while [[ $# -gt 0 ]]; do
        extra="$extra, \"$1\": \"$2\""
        shift 2
    done

    printf '{"timestamp":"%s","level":"%s","pid":%d,"message":"%s"%s}\\n' \\
        "$(date -u +%Y-%m-%dT%H:%M:%SZ)" \\
        "$level" \\
        "$$" \\
        "$message" \\
        "$extra"
}

# Usage
log_json "INFO" "User logged in" "user" "john" "ip" "192.168.1.1"
# Output: {"timestamp":"2024-01-15T10:30:00Z","level":"INFO","pid":1234,"message":"User logged in", "user": "john", "ip": "192.168.1.1"}

# Key-value logging (syslog style)
log_kv() {
    local level="$1"
    local message="$2"
    shift 2

    local kv=""
    while [[ $# -gt 0 ]]; do
        kv="$kv $1=\"$2\""
        shift 2
    done

    echo "[$(date '+%Y-%m-%d %H:%M:%S')] $level: $message$kv"
}

# Usage
log_kv "INFO" "Request completed" "method" "GET" "path" "/api" "status" "200"

Debug Logging Techniques

Advanced techniques for troubleshooting complex scripts.

# Function entry/exit logging
log_function() {
    local func="${FUNCNAME[1]}"
    log_debug "Entering: $func($*)"
}

log_function_exit() {
    local func="${FUNCNAME[1]}"
    local code="${1:-0}"
    log_debug "Exiting: $func (code=$code)"
}

# Wrap function with logging
process_data() {
    log_function "$@"

    # Do work...
    local result="success"

    log_function_exit 0
    return 0
}

# Variable dump
dump_vars() {
    log_debug "=== Variable Dump ==="
    local var
    for var in "$@"; do
        log_debug "  $var=${!var:-}"
    done
}

# Execution trace for specific section
trace_on() {
    set -x
}

trace_off() {
    set +x
}

# Conditional trace
[[ "${TRACE:-false}" == "true" ]] && set -x

# Stack trace on error
print_stack() {
    local i
    echo "Stack trace:" >&2
    for ((i=1; i<${#FUNCNAME[@]}; i++)); do
        echo "  $i: ${FUNCNAME[i]}() at ${BASH_SOURCE[i]}:${BASH_LINENO[i-1]}" >&2
    done
}
trap 'print_stack' ERR

Common Mistakes

# Wrong - password in logs!
log "Connecting with password: $DB_PASSWORD"

# Correct - mask sensitive data
log "Connecting with password: ****"
log "Connecting as user: $DB_USER"

# Wrong - no context
echo "Starting backup"

# Correct - when did it happen?
log "Starting backup"  # Includes timestamp

# Wrong - always prints debug
echo "DEBUG: var=$var"

# Correct - controlled by flag
log_debug "var=$var"  # Only shows when DEBUG=true

Exercise: Complete Logging System

#!/usr/bin/env bash
# logging.sh - Reusable logging library

# Configuration (via environment)
LOG_LEVEL="${LOG_LEVEL:-INFO}"
LOG_FILE="${LOG_FILE:-}"
LOG_FORMAT="${LOG_FORMAT:-text}"  # text or json

# Level values
declare -A LOG_LEVELS=(
    [DEBUG]=0 [INFO]=1 [WARN]=2 [ERROR]=3
)

# Initialize
_log_init() {
    if [[ -n "$LOG_FILE" ]]; then
        mkdir -p "$(dirname "$LOG_FILE")" 2>/dev/null
    fi
}

# Core log function
_log() {
    local level="$1"
    local message="$2"

    # Check level threshold
    local level_val=${LOG_LEVELS[$level]:-1}
    local threshold=${LOG_LEVELS[$LOG_LEVEL]:-1}
    [[ $level_val -lt $threshold ]] && return 0

    local timestamp=$(date '+%Y-%m-%d %H:%M:%S')
    local output

    if [[ "$LOG_FORMAT" == "json" ]]; then
        output=$(printf '{"ts":"%s","level":"%s","pid":%d,"msg":"%s"}' \\
            "$timestamp" "$level" "$$" "$message")
    else
        output="[$timestamp] [$$] $level: $message"
    fi

    # Output to console
    if [[ "$level" == "ERROR" || "$level" == "WARN" ]]; then
        echo "$output" >&2
    else
        echo "$output"
    fi

    # Output to file
    [[ -n "$LOG_FILE" ]] && echo "$output" >> "$LOG_FILE"
}

# Public functions
log_debug() { _log "DEBUG" "$*"; }
log_info()  { _log "INFO" "$*"; }
log_warn()  { _log "WARN" "$*"; }
log_error() { _log "ERROR" "$*"; }

# Initialize on source
_log_init

# Example usage when run directly
if [[ "${BASH_SOURCE[0]}" == "${0}" ]]; then
    log_debug "Debug message"
    log_info "Info message"
    log_warn "Warning message"
    log_error "Error message"
fi

Summary

What's Next?

Scripts often need external Configuration Files. Next, you'll learn to load, parse, and validate configuration from files and environment variables!