7.9 Common Tracing Patterns
Every application has recurring execution patterns: web requests flowing through middleware, database queries executing through ORMs, authentication checks happening at system boundaries. These patterns repeat across codebases. Learning to recognize and trace them gives you a template for understanding any unfamiliar system quickly.
This section shows you the most common execution patterns you'll encounter, with concrete tracing strategies for each. These aren't abstract conceptsβthey're real patterns with specific tools and techniques that work.
7.9.1 Web Request Flow Tracing
Web frameworks follow a predictable execution pattern: request arrives β routing β middleware β controller/view β response. Understanding this pattern lets you trace any web request systematically.
The Universal Web Request Pattern:
HTTP Request arrives
β
Web Server (nginx, Apache, built-in)
β
WSGI/ASGI Server (gunicorn, uvicorn, Node.js)
β
Framework Request Handler
β
Routing (URL β Handler mapping)
β
Middleware Chain (authentication, logging, etc.)
β
View/Controller Function
β
Business Logic
β
Template/Serializer (response generation)
β
Middleware Chain (reverse order)
β
HTTP Response returns
Every web framework follows this pattern, though the naming varies (Django calls them "middleware," Express calls them "middleware," FastAPI calls them "dependencies").
Entry Point: HTTP Server/Framework Router
Start tracing at the entry point. In Django:
# Django automatically routes based on urls.py
# Set a breakpoint in your view function
# accounts/views.py
def user_profile(request, username):
# β BREAKPOINT HERE
# Execution pauses when /users/<username>/ is requested
user = get_object_or_404(User, username=username)
return render(request, 'profile.html', {'user': user})
In Express:
// server.js
app.get('/users/:username', (req, res) => {
// β BREAKPOINT HERE
const { username } = req.params;
const user = await User.findOne({ username });
res.render('profile', { user });
});
The First Question to Answer: "Did my breakpoint even trigger?" If not, either:
-
The URL doesn't match your route (check routing configuration)
-
The request is being handled by a different handler (check route priority)
-
Middleware is rejecting the request before it reaches your handler (check middleware logs)
Middleware Chain Visualization
Middleware executes in order before your view, then in reverse order after. Visualize this:
Request β
AuthenticationMiddleware
SecurityMiddleware
SessionMiddleware
YOUR VIEW EXECUTES HERE
SessionMiddleware (response processing)
SecurityMiddleware (response processing)
AuthenticationMiddleware (response processing)
β Response
Tracing Middleware in Django:
Django Debug Toolbar shows you which middleware ran and in what order. But to understand what each middleware does:
# settings.py
MIDDLEWARE = [
'django.middleware.security.SecurityMiddleware', # β Set breakpoint in source
'django.contrib.sessions.middleware.SessionMiddleware',
'django.middleware.common.CommonMiddleware',
'django.contrib.auth.middleware.AuthenticationMiddleware',
# ...
]
Find the middleware source code:
# In your debugger or IPython
import django.contrib.auth.middleware
import inspect
print(inspect.getfile(django.contrib.auth.middleware.AuthenticationMiddleware))
# /path/to/venv/lib/python3.9/site-packages/django/contrib/auth/middleware.py
# Open that file and set a breakpoint in the process_request method
When you make a request, execution will pause in each middleware, showing you:
-
What the middleware checks (authentication, CSRF tokens, sessions)
-
What it modifies (request.user, request.session)
-
When it short-circuits (returns a response early, bypassing your view)
Real Scenario: Your view never executes. You set a breakpoint in the view function, but it never triggers. Trace the middleware:
# Set breakpoints in middleware
# django/contrib/auth/middleware.py
class AuthenticationMiddleware:
def process_request(self, request):
# β BREAKPOINT HERE
if not request.user.is_authenticated:
return HttpResponseRedirect('/login/') # β This is why your view never runs
return None # Continue to next middleware
The middleware is redirecting unauthenticated users before your view executes. That's the insight you needed.
View/Controller Execution
Once middleware completes, your view/controller executes. This is where business logic happens:
def user_profile(request, username):
# Phase 1: Data retrieval
user = get_object_or_404(User, username=username) # β BREAKPOINT
posts = user.posts.all()[:10] # β BREAKPOINT
# Phase 2: Permissions check
if not can_view_profile(request.user, user): # β BREAKPOINT
return HttpResponseForbidden()
# Phase 3: Response generation
return render(request, 'profile.html', { # β BREAKPOINT
'user': user,
'posts': posts,
})
Strategic Breakpoints: Set them at phase boundaries:
-
Before data retrieval
-
After data retrieval (inspect what was loaded)
-
Before permission checks
-
Before response generation
Template/Serializer Rendering
Response generation often involves templates (HTML) or serializers (JSON). This is where data transforms into output.
For Django templates:
return render(request, 'profile.html', {
'user': user, # β These become template variables
'posts': posts,
})
The template receives these variables and renders HTML. To trace template rendering:
# Enable template debugging
# settings.py
TEMPLATES = [{
'OPTIONS': {
'debug': True, # Shows template source in errors
}
}]
Django Debug Toolbar's Templates panel shows:
-
Which templates rendered
-
Template inheritance chain (base.html β profile.html)
-
Context variables passed to each template
-
Rendering time per template
Tracing Template Execution:
{# profile.html #}
{% extends "base.html" %}
{% block content %}
{# Set a template breakpoint by causing a deliberate error temporarily #}
{{ user.username }} {# β Add |unknown_filter to cause error and see context #}
{% for post in posts %}
{{ post.title }}
{% endfor %}
{% endblock %}
When you add an invalid filter, Django shows you the full template context in the error page. This reveals what data is available.
For API responses with DRF (Django REST Framework):
from rest_framework import serializers
class UserSerializer(serializers.ModelSerializer):
class Meta:
model = User
fields = ['id', 'username', 'email']
def user_api(request, username):
user = get_object_or_404(User, username=username)
serializer = UserSerializer(user) # β BREAKPOINT HERE
# Inspect serializer.data to see output
return JsonResponse(serializer.data)
Response Construction
The final step is constructing the HTTP response:
response = HttpResponse(content, content_type='application/json')
response['Cache-Control'] = 'no-cache'
response.set_cookie('session_id', session.session_key)
return response
Django Debug Toolbar shows the final response headers and status code. Look for:
-
Redirects (3xx status): Where is it redirecting and why?
-
Headers: What cookies are being set? What caching rules apply?
-
Status codes: Is this a 200 (success) or 500 (error)?
Complete Request Trace Example:
Request: GET /users/john/
1. nginx receives request β passes to gunicorn
2. Django's WSGI handler receives it
3. URL routing: /users/<username>/ β accounts.views.user_profile
4. Middleware chain executes:
- SecurityMiddleware: Checks HTTPS (passes)
- SessionMiddleware: Loads session from cookie (passes)
- AuthenticationMiddleware: Loads user from session (passes)
- CommonMiddleware: Handles trailing slashes (passes)
5. View executes: accounts.views.user_profile
- Queries database: SELECT * FROM users WHERE username='john'
- Checks permissions: user.can_view_profile()
- Loads related data: user.posts.all()
6. Template renders: profile.html
- Extends base.html
- Renders user data and posts
7. Middleware chain processes response (reverse order)
8. HTTP response returned: 200 OK, 2.3KB HTML
The Web Request Tracing Checklist:
-
[ ] Identify the entry point (URL β view/controller mapping)
-
[ ] Trace middleware chain execution
-
[ ] Set breakpoints in the view/controller
-
[ ] Inspect data retrieval queries
-
[ ] Check permission/validation logic
-
[ ] Trace template/serializer rendering
-
[ ] Verify response construction
7.9.2 Database Interaction Tracing
Database queries are where web applications spend most of their time. Understanding when and how queries execute is critical for both correctness and performance.
ORM Query Generation Points
ORMs like Django's ORM or SQLAlchemy generate SQL from Python code. The challenge: the code that defines a query is not the code that executes it.
# This line DOES NOT execute a query
users = User.objects.filter(is_active=True)
# This line DOES execute a query
for user in users:
print(user.username) # β Query executes HERE
This lazy evaluation confuses many developers. To trace effectively, understand when queries execute:
Django ORM Query Execution Triggers:
# These DON'T execute queries (lazy):
queryset = User.objects.filter(is_active=True)
queryset = queryset.order_by('username')
queryset = queryset.select_related('profile')
# These DO execute queries (eager):
list(queryset) # Convert to list
queryset.count() # Count rows
queryset.first() # Get first row
queryset[0] # Index access
bool(queryset) # Boolean check
for item in queryset: # Iteration
pass
Tracing Query Execution:
Use Django Debug Toolbar's SQL panel to see exactly when queries run:
def user_list(request):
print("Before queryset creation")
users = User.objects.filter(is_active=True) # No query yet
print("After queryset creation")
print("Before iteration")
for user in users: # Query executes here
print(user.username)
print("After iteration")
return HttpResponse("Done")
Check Debug Toolbar's SQL panel. You'll see:
Query 1: SELECT * FROM users WHERE is_active = 1
Called from: user_list (views.py:23)
Time: 15ms
The query executed during iteration, not during queryset creation.
SQL Execution Visualization
Django Debug Toolbar shows the actual SQL that runs:
-- What you wrote:
User.objects.filter(is_active=True).select_related('profile')
-- What executes:
SELECT users.id, users.username, users.email,
profiles.id, profiles.avatar, profiles.bio
FROM users
LEFT OUTER JOIN profiles ON (users.id = profiles.user_id)
WHERE users.is_active = 1
Key Insight: The ORM generates a LEFT OUTER JOIN for select_related(). Understanding this mapping from Python to SQL helps you reason about performance.
N+1 Query Detection
The most common Django performance problem:
# views.py
def user_list(request):
users = User.objects.all() # Query 1: SELECT * FROM users
for user in users:
print(user.profile.avatar) # Query 2, 3, 4, ... N+1
# Each iteration executes: SELECT * FROM profiles WHERE user_id = ?
If you have 100 users, this executes 101 queries (1 + 100).
Django Debug Toolbar Detection:
The SQL panel highlights duplicate queries:
β οΈ Similar queries executed 100 times:
SELECT * FROM profiles WHERE user_id = ?
From: user_list (views.py:45)
Time: 1,245ms total
The Fix:
def user_list(request):
# Use select_related to JOIN profiles in the initial query
users = User.objects.select_related('profile').all()
# Query: SELECT * FROM users LEFT JOIN profiles ...
for user in users:
print(user.profile.avatar) # No additional queries!
Now: 1 query instead of 101.
Tracing Complex ORM Operations:
When you see complex querysets, trace them step by step:
# Complex queryset
recent_posts = (
Post.objects
.filter(published=True)
.select_related('author')
.prefetch_related('comments')
.annotate(comment_count=Count('comments'))
.order_by('-created_at')[:10]
)
# Trace it:
# 1. Set a breakpoint before the queryset executes
# 2. Check Debug Toolbar's SQL panel
# 3. Identify which SQL queries result from this queryset
You'll see:
-- Query 1: Main posts query
SELECT posts.*, users.username, COUNT(comments.id) as comment_count
FROM posts
LEFT JOIN users ON posts.author_id = users.id
LEFT JOIN comments ON posts.id = comments.post_id
WHERE posts.published = 1
GROUP BY posts.id
ORDER BY posts.created_at DESC
LIMIT 10
-- Query 2: Prefetch related comments
SELECT comments.*
FROM comments
WHERE comments.post_id IN (1, 2, 3, 4, 5, 6, 7, 8, 9, 10)
Notice: select_related creates a JOIN (one query), while prefetch_related creates a separate query with an IN clause. Understanding this difference is crucial for optimization.
Transaction Boundary Identification
Django wraps views in database transactions by default (when ATOMIC_REQUESTS is True). Understanding transaction boundaries prevents data corruption.
# settings.py
DATABASES = {
'default': {
'ATOMIC_REQUESTS': True, # Each view is a transaction
}
}
What This Means:
def create_user(request):
# Transaction starts here β
user = User.objects.create(username='john')
profile = Profile.objects.create(user=user)
# If this raises an exception:
send_welcome_email(user.email) # β Exception here
# Then both user AND profile creation roll back
# Transaction ends here β
return HttpResponse("Done")
Tracing Transactions:
from django.db import transaction
def create_user(request):
print(f"In transaction: {transaction.get_autocommit()}") # False if in transaction
with transaction.atomic():
print("Starting explicit transaction")
user = User.objects.create(username='john')
profile = Profile.objects.create(user=user)
print("Transaction will commit when block exits")
print("Transaction committed")
return HttpResponse("Done")
Debugging Transaction Issues:
# Problem: Why did my database save not persist?
def process_payment(request):
user = User.objects.get(id=request.user.id)
user.balance -= 100
user.save() # β This SEEMS to save
# But then:
charge_credit_card(user) # β This raises an exception
# Since we're in a transaction, the save() rolls back
# User balance never actually changed in the database
The Fix: Use nested transactions explicitly:
from django.db import transaction
def process_payment(request):
user = User.objects.get(id=request.user.id)
# Save balance change in its own transaction
with transaction.atomic():
user.balance -= 100
user.save()
# This commits immediately
# Now charge the card (separate transaction)
try:
charge_credit_card(user)
except PaymentError:
# Balance was already saved, so we need to refund
with transaction.atomic():
user.balance += 100
user.save()
The Database Tracing Pattern:
-
Use Django Debug Toolbar to see all queries
-
Identify duplicate queries (N+1 problems)
-
Check query timing (slow queries)
-
Verify transaction boundaries (atomic blocks)
-
Inspect actual SQL (understand ORM translation)
-
Profile with database tools (EXPLAIN for slow queries)
7.9.3 Authentication Flow Mapping
Authentication is a cross-cutting concern that touches multiple system layers. Tracing it requires understanding the entire request lifecycle.
Login Request Handling
A login request typically follows this pattern:
User submits login form
β
POST /login/ β LoginView
β
Form validation (username + password)
β
Database query: SELECT * FROM users WHERE username = ?
β
Password verification (hash comparison)
β
Session creation (or token generation)
β
Database write: INSERT INTO sessions ...
β
Set session cookie in response
β
Redirect to authenticated area
Tracing Django Login:
# accounts/views.py
from django.contrib.auth import authenticate, login
def login_view(request):
if request.method == 'POST':
username = request.POST['username'] # β BREAKPOINT 1
password = request.POST['password']
user = authenticate(request, username=username, password=password) # β BREAKPOINT 2
# Step into authenticate() to see password checking
if user is not None:
login(request, user) # β BREAKPOINT 3
# Step into login() to see session creation
return redirect('dashboard')
else:
return HttpResponse("Invalid credentials")
return render(request, 'login.html')
Inside authenticate():
# Step into Django's authenticate function
# django/contrib/auth/__init__.py
def authenticate(request=None, **credentials):
for backend in get_backends(): # β Multiple auth backends
try:
user = backend.authenticate(request, **credentials)
if user is not None:
return user
except PermissionDenied:
break
return None
Key Discovery: Django tries multiple authentication backends until one succeeds. If you have custom authentication (LDAP, OAuth, etc.), trace which backend actually handles the authentication.
Inside login():
# django/contrib/auth/__init__.py
def login(request, user, backend=None):
session_auth_hash = user.get_session_auth_hash()
request.session[SESSION_KEY] = user._meta.pk.value_to_string(user) # β Store user ID
request.session[BACKEND_SESSION_KEY] = backend
request.session[HASH_SESSION_KEY] = session_auth_hash
# This triggers session save
request.session.save() # β Database write
Key Discovery: Login stores the user ID (not the whole user object) in the session. Each subsequent request will query the database to load the user object from this ID.
Session/Token Creation
For session-based auth:
# Django session middleware
class SessionMiddleware:
def process_request(self, request):
session_key = request.COOKIES.get(settings.SESSION_COOKIE_NAME)
request.session = SessionStore(session_key) # β Loads from database
For token-based auth (JWT):
from rest_framework_simplejwt.tokens import RefreshToken
def login_api(request):
user = authenticate(username=username, password=password)
if user:
refresh = RefreshToken.for_user(user)
return JsonResponse({
'refresh': str(refresh),
'access': str(refresh.access_token),
})
Tracing Token Generation:
# Step into RefreshToken.for_user()
# rest_framework_simplejwt/tokens.py
@classmethod
def for_user(cls, user):
token = cls()
token['user_id'] = user.id # β Payload contains user ID
token['username'] = user.username
return token
Key Discovery: JWTs encode user data in the token itself. No database query needed to verify them (until they expire).
Middleware Authentication Checks
Every authenticated request goes through authentication middleware:
# Django's authentication middleware
class AuthenticationMiddleware:
def process_request(self, request):
# Get user ID from session
user_id = request.session.get('_auth_user_id')
if user_id:
# Query database for user object
backend = request.session.get('_auth_user_backend')
user = backend.get_user(user_id) # β Database query
request.user = user
else:
request.user = AnonymousUser()
This Means: Every authenticated request executes a database query to load the user object, even if the session is valid. This is a common performance target:
# Optimization: Cache user objects
from django.core.cache import cache
class CachedAuthenticationMiddleware:
def process_request(self, request):
user_id = request.session.get('_auth_user_id')
if user_id:
# Check cache first
cache_key = f'user_{user_id}'
user = cache.get(cache_key)
if user is None:
# Cache miss: query database
user = User.objects.get(id=user_id)
cache.set(cache_key, user, timeout=300) # 5 minutes
request.user = user
Permission Verification Chains
After authentication, permission checks happen:
from django.contrib.auth.decorators import login_required, permission_required
@login_required # β Decorator 1: Checks authentication
@permission_required('accounts.can_edit_profile') # β Decorator 2: Checks permissions
def edit_profile(request, user_id):
# Only reaches here if authenticated AND has permission
pass
Tracing Permission Checks:
# Step into permission_required decorator
# django/contrib/auth/decorators.py
def permission_required(perm):
def decorator(view_func):
def wrapped_view(request, *args, **kwargs):
if not request.user.has_perm(perm): # β Permission check
return HttpResponseForbidden()
return view_func(request, *args, **kwargs)
return wrapped_view
return decorator
Inside has_perm():
# django/contrib/auth/models.py
class User(AbstractBaseUser):
def has_perm(self, perm):
# Queries user_permissions and group permissions
return perm in self.get_all_permissions() # β Can be N queries!
Key Discovery: Permission checking can trigger multiple database queries if not optimized with prefetch_related('groups', 'user_permissions').
Complete Authentication Trace:
User submits login (POST /login/)
β
LoginView receives request
β
AuthenticationMiddleware: request.user = AnonymousUser (no session yet)
β
View calls authenticate(username, password)
β
For each authentication backend:
ModelBackend.authenticate()
β Query: SELECT * FROM users WHERE username = 'john'
β Password check: bcrypt.verify(password, user.password_hash)
β Return user object if valid
β
View calls login(request, user)
β Store user ID in session: session['_auth_user_id'] = user.id
β Save session: INSERT INTO django_session ...
β Set cookie: Set-Cookie: sessionid=abc123...
β
Redirect to /dashboard/
β
--- New request for /dashboard/ ---
β
AuthenticationMiddleware runs again
β Read cookie: sessionid=abc123...
β Load session: SELECT * FROM django_session WHERE session_key = 'abc123'
β Get user ID from session: user_id = session['_auth_user_id']
β Load user: SELECT * FROM users WHERE id = user_id
β Set request.user = user object
β
View decorator @login_required checks request.user.is_authenticated
β True: proceed to view
β False: redirect to login
7.9.4 Background Job Tracing (Python)
Background jobs execute outside the request/response cycle. Tracing them requires different tools and techniques because you can't use Django Debug Toolbar or request-based debugging.
Task Queue Entry Points (Celery, RQ, Dramatiq)
Background jobs start when code calls task.delay() or task.apply_async():
# accounts/views.py
def register_user(request):
# ... create user ...
# Queue background task
send_welcome_email.delay(user.id) # β Task queued, not executed
return redirect('welcome')
What Actually Happens:
# When you call .delay():
send_welcome_email.delay(user.id)
β
Celery serializes task: {'task': 'send_welcome_email', 'args': [42]}
β
Writes to message broker (Redis/RabbitMQ):
LPUSH celery {'task': 'send_welcome_email', 'args': [42]}
β
Returns immediately (non-blocking)
β
--- Meanwhile, in a separate worker process ---
β
Celery worker reads from broker:
BRPOP celery β {'task': 'send_welcome_email', 'args': [42]}
β
Worker deserializes and executes task:
send_welcome_email(42)
Tracing Task Queuing:
# Add logging to see when tasks are queued
import logging
logger = logging.getLogger(__name__)
def register_user(request):
user = User.objects.create(...)
logger.info(f"Queuing welcome email for user {user.id}")
result = send_welcome_email.delay(user.id)
logger.info(f"Task queued with ID: {result.id}")
return redirect('welcome')
Worker Execution Flow
The task executes in a completely separate process:
# accounts/tasks.py
from celery import shared_task
@shared_task
def send_welcome_email(user_id):
print(f"Task starting for user {user_id}") # β Prints to worker console, not web console
user = User.objects.get(id=user_id) # β Separate database connection
send_mail(
subject="Welcome!",
message=f"Welcome, {user.username}!",
from_email="noreply@example.com",
recipient_list=[user.email],
)
print("Email sent successfully")
Debugging Workers:
Start a Celery worker in debug mode:
# Terminal 1: Start worker with logging
celery -A myproject worker --loglevel=debug
# You'll see:
# [2024-01-15 10:30:45] Received task: send_welcome_email[abc-123]
# Task starting for user 42
# Email sent successfully
# [2024-01-15 10:30:47] Task send_welcome_email[abc-123] succeeded in 2.1s
Using pdb in Workers:
@shared_task
def send_welcome_email(user_id):
import pdb; pdb.set_trace() # β Debugger opens in worker terminal
user = User.objects.get(id=user_id)
# ... rest of task
When the task runs, pdb opens in the worker terminal. You can inspect variables, step through code, just like regular debugging.
Failure and Retry Mechanisms
Celery automatically retries failed tasks:
@shared_task(bind=True, max_retries=3)
def send_welcome_email(self, user_id):
try:
user = User.objects.get(id=user_id)
send_mail(...)
except SMTPException as exc:
# Retry in 5 minutes
raise self.retry(exc=exc, countdown=300)
Tracing Retries:
Check the worker logs:
[2024-01-15 10:30:45] Task send_welcome_email[abc-123] raised: SMTPException
[2024-01-15 10:30:45] Task send_welcome_email[abc-123] retry in 300s (retry 1/3)
[2024-01-15 10:35:45] Received task: send_welcome_email[abc-123] (retry)
[2024-01-15 10:35:46] Task send_welcome_email[abc-123] succeeded
Debugging Async Tasks
Async Celery tasks use async/await:
@shared_task
async def send_welcome_email(user_id):
user = await User.objects.aget(id=user_id) # Async ORM query
await send_mail_async(...)
Tracing Async Execution:
@shared_task
async def send_welcome_email(user_id):
print(f"Starting async task for user {user_id}")
print("About to query database")
user = await User.objects.aget(id=user_id)
print(f"Loaded user: {user.username}")
print("About to send email")
await send_mail_async(...)
print("Email sent")
The prints appear in the worker console, showing you the execution order of async operations.
Common Background Job Issues:
Issue 1: Task never executes
# Problem: Worker not consuming from the right queue
@shared_task(queue='emails') # β Task sent to 'emails' queue
def send_welcome_email(user_id):
pass
# But worker started without queue specified:
# celery -A myproject worker # β Only consumes from 'celery' queue
# Fix: Start worker for correct queue
# celery -A myproject worker -Q emails,celery
Issue 2: Task fails silently
# Problem: Exception not logged
@shared_task
def send_welcome_email(user_id):
send_mail(...) # β Raises exception, but you never see it
# Fix: Add logging
import logging
logger = logging.getLogger(__name__)
@shared_task
def send_welcome_email(user_id):
try:
send_mail(...)
except Exception as e:
logger.exception(f"Failed to send email for user {user_id}")
raise # Re-raise to trigger retry
Issue 3: Task takes too long
# Use py-spy to profile running worker
# Terminal 1: Start worker
celery -A myproject worker
# Terminal 2: Get worker PID
ps aux | grep celery
# Terminal 3: Profile for 30 seconds
py-spy record -o profile.svg --pid <PID> -- sleep 30
# Trigger the slow task, then check profile.svg
The Background Job Tracing Pattern:
-
Log task queuing in the web process
-
Log task execution in the worker process
-
Use pdb in workers for debugging
-
Check worker logs for errors and retries
-
Profile with py-spy for performance issues
-
Verify queue configuration if tasks don't run
These four patternsβweb requests, database interactions, authentication, and background jobsβcover the majority of code tracing scenarios you'll encounter. Master these patterns, and you can trace any codebase systematically.