Hands-on lab — Day 40: Observability: Logs, Metrics, Traces, and Dashboards

#!/usr/bin/env bash
# Day 040 lab — completed reference: a mini observability pipeline.
#
# It builds all three pillars from nothing but plain log lines:
#   1. an "app" that does work and emits STRUCTURED JSON logs (with an ERROR level)
#   2. METRICS derived from those logs (total, errors, error rate, p95/p50 latency)
#   3. a tiny text DASHBOARD that prints the metrics
#   4. a TRACE: nested span start/end lines for one request, timing reconstructed
#
# Offline, no network, no API key. Uses only bash, grep/sed/awk, and python3
# (preinstalled on macOS and Linux) for the percentile computation.
# The temporary log file is removed automatically on exit.
set -euo pipefail

# --- temp log file, cleaned up on exit -------------------------------------
logfile="$(mktemp -t observe_log.XXXXXX)"
cleanup() { rm -f "${logfile}"; }
trap cleanup EXIT

# --- 1. the "app": do work and emit structured JSON logs -------------------
# 50 requests. Every 8th request fails (level ERROR) and is slow, so the error
# count is deterministic (6 errors). Latencies are deterministic so every run
# of this reference produces the same metrics.
emit_log() {
  # args: level event latency_ms request_id
  local level="$1" event="$2" latency="$3" rid="$4"
  local sec ts
  sec=$(( 10#${rid##*-} % 60 ))
  ts="$(printf '2026-07-12T14:00:%02dZ' "${sec}")"
  printf '{"ts":"%s","level":"%s","event":"%s","request_id":"%s","latency_ms":%d}\n' \
    "${ts}" "${level}" "${event}" "${rid}" "${latency}" >> "${logfile}"
}

run_app() {
  local i level latency rid
  for i in $(seq 1 50); do
    rid="$(printf 'req-%04d' "${i}")"
    if (( i % 8 == 0 )); then
      level="ERROR"
      latency=$(( 2000 + (i % 5) * 300 ))   # slow, failing requests
    else
      level="INFO"
      latency=$(( 90 + (i * 40) % 170 ))     # healthy requests: 90-259 ms
    fi
    emit_log "${level}" "request_complete" "${latency}" "${rid}"
  done
}

# --- 4. a trace: nested span start/end lines for ONE request ----------------
emit_span() {
  # args: phase(start|end) span at_ms
  printf '{"level":"INFO","event":"span_%s","trace_id":"trace-7f3a9c","span":"%s","at_ms":%d}\n' \
    "$1" "$2" "$3" >> "${logfile}"
}
run_traced_request() {
  emit_span start total_request 0
  emit_span start validate_input 0
  emit_span end   validate_input 12
  emit_span start db_query 12
  emit_span end   db_query 552
  emit_span start call_service 552
  emit_span end   call_service 800
  emit_span end   total_request 812
}

# --- 2. derive METRICS from the logs (the three pillars, by hand) ----------
compute_metrics() {
  local total errors rate
  total="$(grep -c '"event":"request_complete"' "${logfile}")"
  errors="$(grep -c '"level":"ERROR"' "${logfile}")"
  # error rate as a percentage, two decimals, computed with awk
  rate="$(awk -v e="${errors}" -v t="${total}" 'BEGIN{ printf "%.2f", (t>0)? (e/t)*100 : 0 }')"

  # p95 and p50 latency: extract the numeric latency_ms of every request, then
  # compute real nearest-rank percentiles in python3.
  local pcts p95 p50
  pcts="$(grep '"event":"request_complete"' "${logfile}" \
    | sed -n 's/.*"latency_ms":\([0-9]*\).*/\1/p' \
    | python3 -c '
import sys, math
vals = sorted(int(x) for x in sys.stdin.read().split())
n = len(vals)
def pct(p):
    if n == 0: return 0
    return vals[math.ceil(p/100*n) - 1]
print(pct(95), pct(50))
')"
  p95="${pcts%% *}"
  p50="${pcts##* }"

  # --- 3. the DASHBOARD ----------------------------------------------------
  echo "=== Observability Dashboard ==="
  printf 'Total requests:   %s\n' "${total}"
  printf 'Errors:           %s\n' "${errors}"
  printf 'Error rate:       %s%%\n' "${rate}"
  printf 'p95 latency (ms): %s\n' "${p95}"
  printf 'p50 latency (ms): %s\n' "${p50}"
}

# --- reconstruct the TRACE timing from the span start/end lines ------------
print_trace() {
  echo "=== Trace: request trace-7f3a9c ==="
  # For each span, pair its start and end at_ms and print the duration, indented
  # so children sit under the parent. python3 parses the JSON span lines (this
  # runs identically on macOS and Linux, unlike GNU-only awk extensions).
  grep '"event":"span_' "${logfile}" | python3 -c '
import sys, json
start, dur, order = {}, {}, []
for line in sys.stdin:
    line = line.strip()
    if not line:
        continue
    r = json.loads(line)
    name = r["span"]
    if r["event"] == "span_start":
        start[name] = r["at_ms"]
        order.append(name)
    else:
        dur[name] = r["at_ms"] - start[name]
for name in order:
    indent = "  " if name == "total_request" else "    "
    print("%sspan %-16s %4d ms" % (indent, name, dur[name]))
'
}

# --- run the pipeline ------------------------------------------------------
run_app
run_traced_request

# Show a few raw structured log lines so the format is visible, including one
# ERROR line so you can see how a failure is recorded.
echo "=== Sample structured logs (2 healthy, 1 error) ==="
grep '"level":"INFO"' "${logfile}" | grep '"event":"request_complete"' | head -n 2
grep '"level":"ERROR"' "${logfile}" | head -n 1
echo

compute_metrics
print_trace
echo "=== End of dashboard ==="

lesson_id: D040
day: 40
kind: data-processing
languages: [bash]
setup_commands:
  - cd labs/sections/computing-foundations/day-040-observability-logs-metrics-traces-and-dashboards
run_commands:
  - bash examples/observe.sh
  - bash starter/observe.sh
test_commands:
  - bash tests/run_tests.sh
cleanup_commands:
  - 'git checkout -- starter/observe.sh  # optional: reset your work'
requires_network: false
requires_api_key: false
estimated_minutes: 30
last_executed: '2026-07-12'
executed_on: 'macOS (Apple Silicon), bash tests/run_tests.sh → 22 checks, 0 failure(s)'

# Dependencies — Day 040 lab

**Two tools, both preinstalled on macOS and Linux:**

- `bash` ≥ 3.2 — the shell that runs the pipeline (preinstalled on macOS and
  every mainstream Linux distribution).
- `python3` — used only for the percentile computation (the p95/p50) and to
  parse the JSON span lines when reconstructing the trace. It ships with macOS
  and nearly every Linux distribution. Check with `python3 --version`.

The lab also uses the standard text utilities `grep`, `sed`, `awk`, `head`,
`seq`, and `mktemp`, all part of the base system on macOS and Linux.

There is deliberately no `requirements.txt` or `package.json`: the lab installs
nothing and reaches no network. If `python3` is somehow missing, install it
from your package manager (for example `sudo apt install python3` on
Debian/Ubuntu); everything else is already present.

# Observability worksheet — Day 040

Fill this in from a real run of your completed `starter/observe.sh` (or the
reference `examples/observe.sh`). Keep it — it is the template you will reuse
when you instrument a real service later.

## The metrics from my run

| Metric | My value |
| --- | --- |
| Total requests | |
| Error count | |
| Error rate (%) | |
| p95 latency (ms) | |
| p50 latency (ms) | |

## The one thing a dashboard should alert on

Write the single alert you would set for this service. State it as a **symptom
the user feels**, not an internal cause, and give a concrete threshold and a
duration.

- Alert when: ______________________________________________
- Because (the user impact): ________________________________

Example shape: "Page when the error rate stays above 5% for 5 minutes, because
that means more than one user in twenty is seeing failures."

## If this service suddenly felt slow, which pillar would I check first?

In three or four sentences, name which of the three pillars (metrics, traces,
or logs) you would consult first, and what each would tell you next.

______________________________________________________________
______________________________________________________________
______________________________________________________________

## One thing that surprised me

One or two sentences.

#!/usr/bin/env bash
# Day 040 lab — STARTER: build a mini observability pipeline.
#
# The "app" that emits structured JSON logs and the trace reconstruction are
# provided and working. YOUR JOB is the four numbered exercises below, which
# build the three pillars from those logs. Each exercise names the exact
# command to use. Replace every placeholder, then run:  bash starter/observe.sh
# Check the finished reference any time:               bash examples/observe.sh
set -euo pipefail

# --- temp log file, cleaned up on exit (provided) --------------------------
logfile="$(mktemp -t observe_log.XXXXXX)"
cleanup() { rm -f "${logfile}"; }
trap cleanup EXIT

# --- the "app": emits structured JSON logs, 6 of 50 requests fail (provided)
emit_log() {
  local level="$1" event="$2" latency="$3" rid="$4"
  local sec ts
  sec=$(( 10#${rid##*-} % 60 ))
  ts="$(printf '2026-07-12T14:00:%02dZ' "${sec}")"
  printf '{"ts":"%s","level":"%s","event":"%s","request_id":"%s","latency_ms":%d}\n' \
    "${ts}" "${level}" "${event}" "${rid}" "${latency}" >> "${logfile}"
}
run_app() {
  local i level latency rid
  for i in $(seq 1 50); do
    rid="$(printf 'req-%04d' "${i}")"
    if (( i % 8 == 0 )); then
      level="ERROR"; latency=$(( 2000 + (i % 5) * 300 ))
    else
      level="INFO";  latency=$(( 90 + (i * 40) % 170 ))
    fi
    emit_log "${level}" "request_complete" "${latency}" "${rid}"
  done
}

# --- the trace: nested span start/end lines for one request (provided) ------
emit_span() {
  printf '{"level":"INFO","event":"span_%s","trace_id":"trace-7f3a9c","span":"%s","at_ms":%d}\n' \
    "$1" "$2" "$3" >> "${logfile}"
}
run_traced_request() {
  emit_span start total_request 0
  emit_span start validate_input 0; emit_span end validate_input 12
  emit_span start db_query 12;      emit_span end db_query 552
  emit_span start call_service 552; emit_span end call_service 800
  emit_span end   total_request 812
}
print_trace() {
  echo "=== Trace: request trace-7f3a9c ==="
  grep '"event":"span_' "${logfile}" | python3 -c '
import sys, json
start, dur, order = {}, {}, []
for line in sys.stdin:
    line = line.strip()
    if not line: continue
    r = json.loads(line)
    name = r["span"]
    if r["event"] == "span_start":
        start[name] = r["at_ms"]; order.append(name)
    else:
        dur[name] = r["at_ms"] - start[name]
for name in order:
    indent = "  " if name == "total_request" else "    "
    print("%sspan %-16s %4d ms" % (indent, name, dur[name]))
'
}

# ===========================================================================
# YOUR WORK STARTS HERE. Run the app first so the log file exists.
# ===========================================================================
run_app
run_traced_request

# Sample of the structured logs the app just wrote (provided, so you can see
# the format you are working with — two healthy lines and one error line).
echo "=== Sample structured logs (2 healthy, 1 error) ==="
grep '"level":"INFO"' "${logfile}" | grep '"event":"request_complete"' | head -n 2
grep '"level":"ERROR"' "${logfile}" | head -n 1
echo

# ---------------------------------------------------------------------------
# EXERCISE 1: emit ONE structured log line to prove you can produce the format.
# Replace the echo placeholder with a printf that prints a single JSON object with the keys
# ts, level, event, and latency_ms (any sample values are fine). Example shape:
#   printf '{"ts":"2026-07-12T14:00:00Z","level":"INFO","event":"demo","latency_ms":123}\n'
echo "=== Your structured log line (Exercise 1) ==="
echo 'FILL_ME'   # <- replace this echo with your printf that prints one JSON log line
echo

# total requests = number of request_complete lines (provided, uses grep -c)
total="$(grep -c '"event":"request_complete"' "${logfile}")"

# ---------------------------------------------------------------------------
# EXERCISE 2: count the ERROR requests.
# Set `errors` to the number of log lines whose level is ERROR, using:
#   grep -c '"level":"ERROR"' "${logfile}"
errors="FILL_ME"

# ---------------------------------------------------------------------------
# EXERCISE 3: compute the error RATE as a percentage with two decimals.
# Use awk with the two numbers you already have. Template:
#   awk -v e="${errors}" -v t="${total}" 'BEGIN{ printf "%.2f", (t>0)?(e/t)*100:0 }'
rate="FILL_ME"

# ---------------------------------------------------------------------------
# EXERCISE 4: compute the p95 latency (a real nearest-rank percentile).
# Extract the latency_ms of every request and pipe it to python3. Template:
#   grep '"event":"request_complete"' "${logfile}" \
#     | sed -n 's/.*"latency_ms":\([0-9]*\).*/\1/p' \
#     | python3 -c 'import sys,math; v=sorted(int(x) for x in sys.stdin.read().split()); print(v[math.ceil(0.95*len(v))-1])'
p95="FILL_ME"

# p50 (median) latency is provided as a worked example of the same technique.
p50="$(grep '"event":"request_complete"' "${logfile}" \
  | sed -n 's/.*"latency_ms":\([0-9]*\).*/\1/p' \
  | python3 -c 'import sys,math; v=sorted(int(x) for x in sys.stdin.read().split()); print(v[math.ceil(0.50*len(v))-1])')"

# --- the DASHBOARD (provided) ----------------------------------------------
echo "=== Observability Dashboard ==="
printf 'Total requests:   %s\n' "${total}"
printf 'Errors:           %s\n' "${errors}"
printf 'Error rate:       %s%%\n' "${rate}"
printf 'p95 latency (ms): %s\n' "${p95}"
printf 'p50 latency (ms): %s\n' "${p50}"
print_trace
echo "=== End of dashboard ==="

#!/usr/bin/env bash
# Tests for the Day 040 lab. Run from the lab directory:
#   bash tests/run_tests.sh
#
# Verifies the observability pipeline: structured JSON logs are emitted, the
# error count and rate match the known injected errors (6 of 50 = 12.00%), and
# a numeric p95 latency is computed. Runs fully offline; exits 0 on success.
set -u

lab_dir="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)"
failures=0
checks=0

check() {
  local label="$1" ok="$2"
  checks=$((checks + 1))
  if [ "${ok}" = "yes" ]; then
    echo "  ok: ${label}"
  else
    echo "  FAIL: ${label}"
    failures=$((failures + 1))
  fi
}

run_pipeline_checks() {
  local script="$1" strict="$2" output
  echo "Testing ${script} ..."
  if ! output="$(bash "${script}" 2>&1)"; then
    check "script exits successfully" "no"
    echo "${output}" | sed 's/^/    /'
    return
  fi
  check "script exits successfully" "yes"

  # Pillar 1: structured JSON logs are emitted (a line with the required keys).
  if echo "${output}" | grep -Eq '\{"ts":".*","level":".*","event":"request_complete".*"latency_ms":[0-9]+\}'; then
    check "emits structured JSON request logs with latency_ms" "yes"
  else
    check "emits structured JSON request logs with latency_ms" "no"
  fi
  # At least one ERROR-level line exists in the emitted logs.
  echo "${output}" | grep -q '"level":"ERROR"' && \
    check "emits at least one ERROR-level log line" "yes" || \
    check "emits at least one ERROR-level log line" "no"

  # Dashboard shape: all five metric lines present.
  for field in "Total requests:" "Errors:" "Error rate:" "p95 latency (ms):" "p50 latency (ms):"; do
    echo "${output}" | grep -q "^${field}" && check "dashboard prints '${field}'" "yes" || check "dashboard prints '${field}'" "no"
  done

  # Trace: nested spans reconstructed.
  echo "${output}" | grep -q "span total_request" && \
    check "trace reconstructs the total_request span" "yes" || \
    check "trace reconstructs the total_request span" "no"

  if [ "${strict}" = "strict" ]; then
    # Pillar 2: metrics match the known injected errors (6 of 50).
    total="$(echo "${output}" | sed -n 's/^Total requests:[[:space:]]*//p')"
    errors="$(echo "${output}" | sed -n 's/^Errors:[[:space:]]*//p')"
    rate="$(echo "${output}" | sed -n 's/^Error rate:[[:space:]]*//p')"
    p95="$(echo "${output}" | sed -n 's/^p95 latency (ms):[[:space:]]*//p')"

    [ "${total}" = "50" ] && check "total requests is 50" "yes" || check "total requests is 50 (got '${total}')" "no"
    [ "${errors}" = "6" ] && check "error count matches known injected errors (6)" "yes" || check "error count is 6 (got '${errors}')" "no"
    [ "${rate}" = "12.00%" ] && check "error rate is 12.00%" "yes" || check "error rate is 12.00% (got '${rate}')" "no"
    case "${p95}" in
      '' | *[!0-9]*) check "p95 latency is a number (got '${p95}')" "no" ;;
      *)             check "p95 latency is a number" "yes" ;;
    esac
  fi
}

# The completed reference must pass every strict check.
run_pipeline_checks "${lab_dir}/examples/observe.sh" strict

# The starter ships with FILL_ME placeholders; once the learner has replaced
# them all, hold their script to the same strict standard.
if grep -q 'FILL_ME' "${lab_dir}/starter/observe.sh"; then
  echo "Note: starter/observe.sh still has unfinished exercises (FILL_ME) — testing structure only."
  run_pipeline_checks "${lab_dir}/starter/observe.sh" lenient
else
  run_pipeline_checks "${lab_dir}/starter/observe.sh" strict
fi

echo
echo "${checks} checks, ${failures} failure(s)."
[ "${failures}" -eq 0 ]