Tracing State Changes
Now that state can only change through controlled methods, we can add visibility into every change โ turning "why is this value wrong" from a mystery into a readable trace.
Watching a value change, one step at a time.
1. Learning Objective
By the end of this session you will be able to:
- Add a print-based trace to a controlled state-change method
- Use Python's logging module for a more structured trace than print()
- Explain the difference between a debug-level and a warning-level log message
- Track how many times a state-change method has been called, as a simple instrumentation pattern
- Explain why this is only possible because state changes are funneled through methods (Session 21)
2. Pre-Coding Quiz
Answer these before reading the concept explanation or writing any code. It is fine to get these wrong โ that is the point. You need 4/5 to proceed to the lab.
Why does adding a print statement inside set_population (rather than at every call site) give you a complete trace of every population change?
What is the practical difference between logging.debug(...) and logging.warning(...)?
debug is detailed tracing you usually silence in normal use; warning signals something worth noticing. This lets the same codebase be quiet during normal operation and verbose while debugging, without changing any code.A class attribute self._update_count = 0 in __init__, incremented once per call inside set_population, tracks what?
Why is this kind of instrumentation ("count every call", "print every change") realistic to add here but would have been much harder in Session 20's uncontrolled-mutation version?
Should tracing/logging code like this normally raise exceptions or otherwise change the program's actual behavior?
3. The Concept โ Tracing State Changes
Every change funnels through one checkpoint โ one trace line there sees every single change made anywhere in the program.
Why a controlled entry point makes tracing trivial
Because Session 21 forced every population change through set_population and grow_population, adding a trace to those two methods gives complete visibility into every change, anywhere in the program, with no missed call sites.
class Country:
def __init__(self, name, region, population):
self.name = name
self.region = region
self.population = population
def set_population(self, value):
if value < 0:
raise ValueError(f"population must be non-negative, got {value}")
old = self.population
self.population = value
print(f"[trace] {self.name}.population: {old} -> {value}")
A more structured trace with logging
print() works, but Python's built-in logging module gives you severity levels and a consistent format, letting you turn tracing verbosity up or down without touching the code that produces it.
import logging
logging.basicConfig(level=logging.DEBUG, format="%(levelname)s: %(message)s")
class Country:
def __init__(self, name, region, population):
self.name = name
self.region = region
self.population = population
def set_population(self, value):
if value < 0:
logging.warning(f"rejected population {value} for {self.name}")
raise ValueError(f"population must be non-negative, got {value}")
old = self.population
self.population = value
logging.debug(f"{self.name}.population: {old} -> {value}")
debug vs warning severity
debug is for fine-grained detail you usually don't want cluttering normal output. warning flags something worth noticing โ like a rejected change โ without stopping the program the way an unhandled exception would.
logging.basicConfig(level=logging.WARNING) # debug messages now silenced
# This debug call produces no visible output at WARNING level:
logging.debug("population changed")
# This warning still shows, because it meets the configured threshold:
logging.warning("rejected an invalid population value")
Counting calls as lightweight instrumentation
A simple counter attribute, incremented inside the controlled method, tells you how often a state change has actually occurred โ useful for spotting unexpectedly frequent (or absent) updates while debugging.
class Country:
def __init__(self, name, region, population):
self.name = name
self.region = region
self.population = population
self._update_count = 0
def set_population(self, value):
if value < 0:
raise ValueError(f"population must be non-negative, got {value}")
self.population = value
self._update_count += 1
k = Country(name="Kenya", region="Africa", population=54000000)
k.set_population(55000000)
k.set_population(56000000)
print(k._update_count) # 2
4. Lab
What you will build
A file called tracing_lab.py.
Step-by-step instructions
Create the file with logging configured
# tracing_lab.py
import logging
logging.basicConfig(level=logging.DEBUG, format="%(levelname)s: %(message)s")
class Country:
def __init__(self, name, region, population):
self.name = name
self.region = region
self.population = population
self._update_count = 0
Add set_population with both a print trace and a logging.debug trace
def set_population(self, value):
if value < 0:
logging.warning(f"rejected population {value} for {self.name}")
raise ValueError(f"population must be non-negative, got {value}")
old = self.population
self.population = value
self._update_count += 1
print(f"[trace] {self.name}.population: {old} -> {value}")
logging.debug(f"{self.name} update #{self._update_count}")
Make several valid changes and observe both trace channels
k = Country(name="Kenya", region="Africa", population=54000000)
k.set_population(55000000)
k.set_population(56000000)
k.set_population(57000000)
print("Total updates:", k._update_count)
Trigger the warning trace with an invalid change
try:
k.set_population(-1)
except ValueError as e:
print("Caught:", e)
print("Total updates still:", k._update_count) # unchanged โ rejected update did not count
Raise the logging level to WARNING and confirm debug traces go silent
Change the level and re-run a valid update โ the print trace still shows, but the debug log line does not.
logging.getLogger().setLevel(logging.WARNING)
k.set_population(58000000) # print trace still visible; debug log line is now silenced
5. Expected Files Changed
| File | Action | Why |
|---|---|---|
tracing_lab.py |
Created | Adds print and logging traces plus an update counter to the controlled set_population method. |
docs/sessions/session-23/index.html |
Created | This session document. |
6. Commit Checkpoint
Once the lab is complete and you can explain every line, make this exact commit:
git add tracing_lab.py docs/sessions/session-23/index.html
git commit -m "session-23: trace state changes with print, logging, and a call counter"
7. Code Review Checklist
Go through your code line by line and check each item:
8. Post-Coding Quiz
Same 5 questions. Take it again now that you have written and run the code. You need 4/5 to mark this session complete.
Why does adding a print statement inside set_population (rather than at every call site) give you a complete trace of every population change?
What is the practical difference between logging.debug(...) and logging.warning(...)?
debug is detailed tracing you usually silence in normal use; warning signals something worth noticing. This lets the same codebase be quiet during normal operation and verbose while debugging, without changing any code.A class attribute self._update_count = 0 in __init__, incremented once per call inside set_population, tracks what?
Why is this kind of instrumentation ("count every call", "print every change") realistic to add here but would have been much harder in Session 20's uncontrolled-mutation version?
Should tracing/logging code like this normally raise exceptions or otherwise change the program's actual behavior?
9. Reflection Questions
Think through these after the post-quiz. No right answer โ they are for discussion.
- Why does raising the logging level silence debug() calls but not your plain print() calls? What does that tell you about how the two mechanisms are separate?
- If you needed to trace every state change across the WHOLE program (not just Country), what would you need to be true about how ALL your classes handle state, based on Session 21?
- What is the tradeoff of leaving debug-level tracing permanently in the code (as opposed to removing it after debugging is done)?
- How would you use _update_count to detect a bug where population is being changed far more often than expected?
10. What Breaks If This Knowledge Is Missing?
- Debugging without visibility: Without any tracing, tracking down "why did this value change unexpectedly" requires manually stepping through code with a debugger every single time โ tracing built into the controlled entry point gives you a permanent, always-available record instead.
- Validated input (Session 24): The next session tightens validation on the input side. Having tracing already in place means you will be able to directly observe the effect of stricter validation instead of guessing.
- Testing failures (Layer 5): When a test fails in Session 34 because state didn't update as expected, the debugging techniques from this session โ trace prints, logging, counters โ are exactly what you'll reach for to understand why.
11. What We Learned
Python concept mastered: Tracing state changes with print and the logging module's severity levels, plus lightweight call-counting instrumentation.
Unlocks: You can now observe exactly when, how often, and why any piece of controlled state changes โ turning invisible bugs into readable traces.
Next session: Session 24 โ Validating Input. We tighten validation further, handling edge cases in user-supplied input more thoroughly than Session 22 did.