What You'll Build
You will add complete observability instrumentation to CricketPulse's live scoring API — a Python Flask service that fetches ball-by-ball match data and serves it to millions of fans during an India vs Australia T20. The unmonitored service has been experiencing mysterious slowdowns during powerplay overs and nobody knows which component is responsible. By the end of this exercise, you will have instrumented the service with Prometheus metrics (RED: request rate, error rate, duration), structured JSON logs with trace_id correlation, and OpenTelemetry traces broken into granular child spans. You will then trigger a simulated slowdown and use your instrumentation to identify the root cause in under 2 minutes — the practical goal this entire module is building toward.
Prerequisites
- Python 3.9+ installed with pip; virtual environment recommended to isolate dependencies from system Python.
- Basic Flask knowledge: understanding of route decorators, request context, and JSON responses.
- Familiarity with Prometheus metric types: Counter increments, Gauge fluctuates, Histogram buckets observations.
- OpenTelemetry concepts from Lesson 3: TracerProvider, spans, context propagation, and BatchSpanProcessor.
- Docker installed for running a local Prometheus scrape target (optional but recommended for full verification).
Setup & Project Structure
Create a virtual environment and install the four packages required: Flask for the web server, prometheus-client for metric exposition, opentelemetry-sdk for tracing, and opentelemetry-exporter-otlp-proto-grpc for span export. The project structure keeps instrumentation logic in a dedicated `observability.py` module to separate it from business logic in `app.py`, matching the pattern used in production services where the observability setup is maintained independently of feature code.
# Setup commands
python3 -m venv cricketpulse-obs-venv
source cricketpulse-obs-venv/bin/activate
pip install flask prometheus-client opentelemetry-sdk \
opentelemetry-exporter-otlp-proto-grpc \
opentelemetry-instrumentation-flask
# Project structure
cricketpulse-scoring/
├── app.py # Flask routes and business logic
├── observability.py # Metrics, tracer, logger setup
├── match_data.py # Simulated match data with injected slowdown
├── requirements.txt
└── prometheus.yml # Local Prometheus config for scrapingStep 1 — Foundation
In Step 1 you set up the three observability primitives in a dedicated `observability.py` module: the Prometheus metric instruments (Counter, Histogram, Gauge), the OpenTelemetry TracerProvider with BatchSpanProcessor, and the structured JSON logger. Centralising these in one module ensures that every service that imports from it gets consistent metric names, log schema, and trace configuration — the foundation of standardised observability across a microservices fleet.
# observability.py — centralised observability setup
import logging, json, sys
from prometheus_client import Counter, Histogram, Gauge, start_http_server
from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.sdk.resources import Resource
# ── STRUCTURED LOGGER ──────────────────────────────────────────────────────────
class JSONFormatter(logging.Formatter):
def format(self, record):
log_obj = {
'time': self.formatTime(record),
'level': record.levelname,
'service': 'cricketpulse-scoring',
'message': record.getMessage(),
}
if hasattr(record, 'extra'):
log_obj.update(record.extra)
return json.dumps(log_obj)
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(JSONFormatter())
logger = logging.getLogger('cricketpulse')
logger.addHandler(handler)
logger.setLevel(logging.INFO)
# ── PROMETHEUS METRICS ─────────────────────────────────────────────────────────
# RED: Rate, Errors, Duration
HTTP_REQUESTS_TOTAL = Counter(
'cricketpulse_http_requests_total',
'Total HTTP requests',
['method', 'endpoint', 'status_code']
)
HTTP_REQUEST_DURATION_SECONDS = Histogram(
'cricketpulse_http_request_duration_seconds',
'HTTP request duration in seconds',
['method', 'endpoint'],
buckets=[0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0]
)
ACTIVE_MATCH_CONNECTIONS = Gauge(
'cricketpulse_active_match_connections',
'Active WebSocket connections watching live matches'
)
# Start Prometheus metrics endpoint on port 8000
start_http_server(8000)
logger.info('Prometheus metrics server started on :8000')
# ── OPENTELEMETRY TRACER ───────────────────────────────────────────────────────
resource = Resource.create({
'service.name': 'cricketpulse-scoring',
'service.version': '2.0.0',
'deployment.environment': 'development'
})
provider = TracerProvider(resource=resource)
# In development: use ConsoleSpanExporter to print spans to stdout
from opentelemetry.sdk.trace.export import ConsoleSpanExporter
provider.add_span_processor(BatchSpanProcessor(ConsoleSpanExporter()))
trace.set_tracer_provider(provider)
tracer = trace.get_tracer('cricketpulse.scoring', '2.0.0')
logger.info('OpenTelemetry tracer initialised')
Step 2 — Core Logic
Step 2 builds the Flask application routes and wraps them with the observability decorator pattern. The key implementation detail is injecting the active trace_id into every structured log line — this creates the correlation link that enables jumping from a log anomaly to its trace in one click. The match data module includes a deliberately injected 400ms slowdown on the 'get_current_over' endpoint when over_number >= 6 (powerplay), which your instrumentation must detect and diagnose.
# app.py — Flask routes with full observability
import time, functools, json
from flask import Flask, request, jsonify
from observability import (
logger, tracer, HTTP_REQUESTS_TOTAL,
HTTP_REQUEST_DURATION_SECONDS, ACTIVE_MATCH_CONNECTIONS
)
from opentelemetry import trace as otel_trace
from match_data import get_live_score, get_current_over, get_scorecard
app = Flask(__name__)
def observe_request(fn):
"""Decorator: adds RED metrics + structured log + trace span to any route."""
@functools.wraps(fn)
def wrapper(*args, **kwargs):
start = time.time()
endpoint = request.endpoint or 'unknown'
method = request.method
status_code = '200'
with tracer.start_as_current_span(f'http.{method.lower()}.{endpoint}') as span:
span.set_attribute('http.method', method)
span.set_attribute('http.route', request.path)
# Get current trace_id for log correlation
ctx = span.get_span_context()
trace_id = format(ctx.trace_id, '032x') if ctx and ctx.is_valid else 'none'
try:
response = fn(*args, **kwargs)
status_code = str(response.status_code)
span.set_attribute('http.status_code', int(status_code))
return response
except Exception as e:
status_code = '500'
span.record_exception(e)
span.set_status(otel_trace.StatusCode.ERROR, str(e))
raise
finally:
duration = time.time() - start
# METRIC: Red method
HTTP_REQUESTS_TOTAL.labels(method=method, endpoint=endpoint, status_code=status_code).inc()
HTTP_REQUEST_DURATION_SECONDS.labels(method=method, endpoint=endpoint).observe(duration)
# STRUCTURED LOG with trace_id correlation key
logger.info('request completed', extra={
'endpoint': endpoint,
'method': method,
'status_code': status_code,
'duration_ms': round(duration * 1000, 2),
'path': request.path,
'trace_id': trace_id, # ← correlation key
'query_params': dict(request.args)
})
return wrapper
@app.route('/matches/<match_id>/score')
@observe_request
def live_score(match_id: str):
with tracer.start_as_current_span('match.get_live_score') as span:
span.set_attribute('match_id', match_id)
score = get_live_score(match_id)
return jsonify(score)
@app.route('/matches/<match_id>/over/<int:over_number>')
@observe_request
def current_over(match_id: str, over_number: int):
with tracer.start_as_current_span('match.get_current_over') as span:
span.set_attribute('match_id', match_id)
span.set_attribute('over_number', over_number)
# ← This call has a hidden 400ms slowdown when over_number >= 6
over_data = get_current_over(match_id, over_number)
return jsonify(over_data)
@app.route('/matches/<match_id>/scorecard')
@observe_request
def scorecard(match_id: str):
with tracer.start_as_current_span('match.get_scorecard') as span:
span.set_attribute('match_id', match_id)
with tracer.start_as_current_span('db.query.full_scorecard') as db_span:
db_span.set_attribute('db.operation', 'SELECT')
data = get_scorecard(match_id)
return jsonify(data)
if __name__ == '__main__':
ACTIVE_MATCH_CONNECTIONS.set(0)
app.run(host='0.0.0.0', port=5000, debug=False)
Step 3 — Integration & Enhancement
Step 3 creates the simulated match data module with the injected slowdown, and adds the Prometheus configuration for local scraping. The deliberate slowdown — `time.sleep(0.4)` when `over_number >= 6` — simulates a real-world scenario where a cached dataset expires during the powerplay and triggers a slow database fallback. Your instrumentation from Step 2 must surface this as an elevated p99 on the `current_over` endpoint in the Histogram metric and as a slow span in the `match.get_current_over` child span.
# match_data.py — simulated match data with injected powerplay slowdown
import time, random
MATCH_DB = {
'IND_AUS_T20_2024': {
'teams': 'India vs Australia',
'venue': 'Wankhede Stadium, Mumbai',
'current_score': '156/3', 'overs': 17.4,
'run_rate': 8.96, 'required_rate': None,
'batters': [
{'name': 'Virat Kohli', 'runs': 67, 'balls': 48, 'fours': 5, 'sixes': 2},
{'name': 'Hardik Pandya', 'runs': 31, 'balls': 18, 'fours': 2, 'sixes': 2}
],
'bowler': {'name': 'Pat Cummins', 'overs': 3.4, 'runs': 28, 'wickets': 1}
}
}
def get_live_score(match_id: str) -> dict:
"""Fast path — always sub-10ms."""
time.sleep(random.uniform(0.005, 0.015)) # simulate DB read
return MATCH_DB.get(match_id, {'error': 'match not found'})
def get_current_over(match_id: str, over_number: int) -> dict:
"""
INJECTED SLOWDOWN: 400ms additional latency during powerplay (overs 6+).
This simulates a cache miss that triggers a slow DB fallback.
Your instrumentation must detect which endpoint is slow and why.
"""
base_latency = random.uniform(0.010, 0.025)
if over_number >= 6:
# Simulated cache miss + slow DB query
time.sleep(base_latency + 0.400) # ← the bug your traces must find
else:
time.sleep(base_latency)
return {
'over_number': over_number,
'match_id': match_id,
'deliveries': [
{'ball': i+1, 'runs': random.choice([0,0,0,1,1,1,2,4,6,0]),
'bowler': 'Pat Cummins', 'batter': 'Virat Kohli'}
for i in range(min(over_number, 6))
],
'over_total': random.randint(5, 14)
}
def get_scorecard(match_id: str) -> dict:
"""Medium latency — DB query with index."""
time.sleep(random.uniform(0.020, 0.050))
return {**MATCH_DB.get(match_id, {}), 'fall_of_wickets': [
{'wicket': 1, 'score': 42, 'over': 5.3, 'batter': 'Rohit Sharma'},
{'wicket': 2, 'score': 89, 'over': 11.1, 'batter': 'KL Rahul'},
{'wicket': 3, 'score': 124, 'over': 15.5, 'batter': 'Shubman Gill'},
]}
# prometheus.yml — local Prometheus configuration
PROMETHEUS_CONFIG = '''
global:
scrape_interval: 15s
scrape_configs:
- job_name: 'cricketpulse-scoring'
static_configs:
- targets: ['localhost:8000']
metrics_path: '/metrics'
'''
with open('prometheus.yml', 'w') as f:
f.write(PROMETHEUS_CONFIG)
print('prometheus.yml written')
Step 4 — Testing & Verification
Run the Flask service and fire test requests against both the normal and slowdown endpoints. The verification test sends 20 requests to the `current_over` endpoint — 10 for overs 1-5 (fast path) and 10 for overs 6-10 (slow path) — and checks that the Prometheus histogram correctly shows elevated p99 latency for the slow path. Reading the structured logs, you should see `duration_ms` spike from ~15ms to ~420ms precisely at `over_number: 6`, and the console-exported spans should show the `match.get_current_over` child span consuming 400ms of the parent span's total duration.
# Run the service and fire test requests
python3 app.py &
APP_PID=$!
sleep 2
echo "Service started (PID $APP_PID)"
# Test fast path (overs 1-5)
echo "=== Testing fast path (overs 1-5) ==="
for i in 1 2 3 4 5; do
time curl -s http://localhost:5000/matches/IND_AUS_T20_2024/over/$i | python3 -c "import sys,json; d=json.load(sys.stdin); print(f'Over {d[\"over_number\"]}: OK')"
done
# Test slow path (overs 6-10) — should show ~420ms latency
echo "=== Testing slow path (overs 6-10 — expect ~420ms) ==="
for i in 6 7 8 9 10; do
time curl -s http://localhost:5000/matches/IND_AUS_T20_2024/over/$i | python3 -c "import sys,json; d=json.load(sys.stdin); print(f'Over {d[\"over_number\"]}: OK')"
done
# Check Prometheus metrics — should show elevated p99 for current_over
echo "=== Prometheus histogram (current_over endpoint) ==="
curl -s http://localhost:8000/metrics | grep 'cricketpulse_http_request_duration.*current_over'
# Expected output shows:
# cricketpulse_http_request_duration_seconds_bucket{...endpoint="current_over",...le="0.5"} 10 (fast path hits this)
# cricketpulse_http_request_duration_seconds_bucket{...endpoint="current_over",...le="0.5"} 10 (slow path misses 0.5s bucket)
# cricketpulse_http_request_duration_seconds_bucket{...endpoint="current_over",...le="1.0"} 20 (slow path hits 1.0s bucket)
kill $APP_PID
echo "Service stopped"Warning: If you see 'Address already in use' on port 8000, another Prometheus client_library server is already running from a previous test. Run `lsof -ti:8000 | xargs kill -9` to clear the port before restarting. This error occurs because `start_http_server(8000)` in `observability.py` is called when the module is imported, and if the previous process was not cleanly killed, the port remains bound.
Extension Challenge: Add a second Gauge metric called `cricketpulse_cache_hit_ratio` that tracks the ratio of cache hits to total requests on the `current_over` endpoint. When `over_number >= 6`, set the gauge to 0.0 (cache miss); when `over_number < 6`, set it to 1.0 (cache hit). Verify that this gauge drops from 1.0 to 0.0 exactly at over 6 in your Prometheus metrics output — this is the leading indicator that would have triggered an alert before the latency spike was user-visible.
- The observability decorator pattern keeps all telemetry code out of business logic methods, enabling consistent instrumentation across all routes without per-route duplication.
- Injecting `trace_id` into every structured log line creates the correlation key that enables jumping from a log entry directly to its causative trace in Grafana Tempo.
- Prometheus Histogram buckets must be tuned to your expected latency range — default buckets are too coarse for sub-100ms services and too fine for batch processing jobs.
- ConsoleSpanExporter is appropriate for local development; always switch to BatchSpanProcessor with OTLPSpanExporter before deploying to staging or production environments.
- Granular child spans (one per DB call, one per cache operation) are what make traces actionable — a single monolithic span identifies the service but not the sub-operation responsible for latency.
- Simulating failures during development (injected slowdowns, error injection) is the only way to verify that your instrumentation surfaces the right signals under realistic conditions.